diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index d1c6fa7..8da353c 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -8,3 +8,9 @@ - Do not include "issue #N", "triangulate", "hypothesis", or similar investigation language in inline code comments or block comments inside method bodies. Such context belongs in the pull request description, not in the source code. + +## Documentation and tests + +- Always update documentation when public APIs change. +- Always update `README.md` when notable behavior or features are added or modified. +- Always add or update tests for behavior changes. diff --git a/README.md b/README.md index 7df4e90..a48b360 100644 --- a/README.md +++ b/README.md @@ -123,6 +123,25 @@ await dbContext.ExecuteBulkInsertAsync(entities, o => await dbContext.ExecuteBulkInsertReturnEntitiesAsync(entities); ``` +### Logging + +Bulk insert operations emit EF Core-style logs when a logger factory is configured on the `DbContext` options: + +```csharp +services.AddDbContext(options => +{ + options + .UseSqlite(connectionString) + .UseLoggerFactory(loggerFactory) + .UseBulkInsertSqlite(); +}); +``` + +Log events: + +* `1004` (`Information`): bulk insert completion with elapsed time and destination table. +* `1005` (`Debug`): auxiliary SQL commands executed by the library (such as temp-table DDL). + ### Conflict resolution / merge / upsert Conflict resolution works by specifying columns that should be used to detect conflicts and the action to take when diff --git a/docs/documentation.md b/docs/documentation.md index e58fc0d..097c776 100644 --- a/docs/documentation.md +++ b/docs/documentation.md @@ -84,6 +84,25 @@ await dbContext.ExecuteBulkInsertAsync(entities, o => await dbContext.ExecuteBulkInsertReturnEntitiesAsync(entities); ``` +## Logging + +Bulk insert operations emit EF Core-style logs when a logger factory is configured: + +```csharp +services.AddDbContext(options => +{ + options + .UseSqlite(connectionString) + .UseLoggerFactory(loggerFactory) + .UseBulkInsertSqlite(); +}); +``` + +Log events: + +* `1004` (`Information`): bulk insert completion with elapsed time and destination table. +* `1005` (`Debug`): auxiliary SQL commands executed by the library (for example temp-table SQL). + ### Conflict resolution / merge / upsert Conflict resolution works by specifying columns that should be used to detect conflicts and the action to take when diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert.MySql/MySqlBulkInsertProvider.cs b/src/PhenX.EntityFrameworkCore.BulkInsert.MySql/MySqlBulkInsertProvider.cs index fc14d5f..ab00cd7 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert.MySql/MySqlBulkInsertProvider.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert.MySql/MySqlBulkInsertProvider.cs @@ -12,7 +12,7 @@ namespace PhenX.EntityFrameworkCore.BulkInsert.MySql; [UsedImplicitly] -internal class MySqlBulkInsertProvider(ILogger logger) : BulkInsertProviderBase(logger) +internal class MySqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase(loggerFactory) { //language=sql /// diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert.Oracle/OracleBulkInsertProvider.cs b/src/PhenX.EntityFrameworkCore.BulkInsert.Oracle/OracleBulkInsertProvider.cs index b97feab..99db3cd 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert.Oracle/OracleBulkInsertProvider.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert.Oracle/OracleBulkInsertProvider.cs @@ -11,7 +11,7 @@ namespace PhenX.EntityFrameworkCore.BulkInsert.Oracle; [UsedImplicitly] -internal class OracleBulkInsertProvider(ILogger? logger) : BulkInsertProviderBase(logger) +internal class OracleBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase(loggerFactory) { /// protected override string BulkInsertId => "ROWID"; diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert.PostgreSql/PostgreSqlBulkInsertProvider.cs b/src/PhenX.EntityFrameworkCore.BulkInsert.PostgreSql/PostgreSqlBulkInsertProvider.cs index 9f8ee0b..4993b44 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert.PostgreSql/PostgreSqlBulkInsertProvider.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert.PostgreSql/PostgreSqlBulkInsertProvider.cs @@ -15,7 +15,7 @@ namespace PhenX.EntityFrameworkCore.BulkInsert.PostgreSql; [UsedImplicitly] -internal class PostgreSqlBulkInsertProvider(ILogger? logger) : BulkInsertProviderBase(logger) +internal class PostgreSqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase(loggerFactory) { //language=sql /// diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert.SqlServer/SqlServerBulkInsertProvider.cs b/src/PhenX.EntityFrameworkCore.BulkInsert.SqlServer/SqlServerBulkInsertProvider.cs index bedff35..7fb8ed7 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert.SqlServer/SqlServerBulkInsertProvider.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert.SqlServer/SqlServerBulkInsertProvider.cs @@ -10,7 +10,7 @@ namespace PhenX.EntityFrameworkCore.BulkInsert.SqlServer; [UsedImplicitly] -internal class SqlServerBulkInsertProvider(ILogger? logger) : BulkInsertProviderBase(logger) +internal class SqlServerBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase(loggerFactory) { //language=sql /// diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert.Sqlite/SqliteBulkInsertProvider.cs b/src/PhenX.EntityFrameworkCore.BulkInsert.Sqlite/SqliteBulkInsertProvider.cs index 7edca6a..d347dce 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert.Sqlite/SqliteBulkInsertProvider.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert.Sqlite/SqliteBulkInsertProvider.cs @@ -13,7 +13,7 @@ namespace PhenX.EntityFrameworkCore.BulkInsert.Sqlite; [UsedImplicitly] -internal class SqliteBulkInsertProvider(ILogger? logger) : BulkInsertProviderBase(logger) +internal class SqliteBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase(loggerFactory) { private const int MaxParams = 1000; diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertOptionsExtension.cs b/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertOptionsExtension.cs index 6060e64..78523ff 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertOptionsExtension.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertOptionsExtension.cs @@ -16,8 +16,8 @@ public DbContextOptionsExtensionInfo Info public void ApplyServices(IServiceCollection services) { - services.TryAddSingleton(typeof(ILogger<>), typeof(NullLogger<>)); - services.AddSingleton(); + services.TryAddSingleton(); + services.AddScoped(); } public void Validate(IDbContextOptions options) diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertProviderBase.cs b/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertProviderBase.cs index 852ce08..bca7e5e 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertProviderBase.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert/BulkInsertProviderBase.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using System.Runtime.CompilerServices; using Microsoft.EntityFrameworkCore; @@ -11,10 +12,12 @@ namespace PhenX.EntityFrameworkCore.BulkInsert; -internal abstract class BulkInsertProviderBase(ILogger? logger) : BulkInsertProviderUntyped +internal abstract class BulkInsertProviderBase(ILoggerFactory? loggerFactory) : BulkInsertProviderUntyped where TDialect : SqlDialectBuilder, new() where TOptions : BulkInsertOptions, new() { + private ILogger? _logger; + private ILogger? logger => _logger ??= loggerFactory?.CreateLogger(GetType()); protected virtual string BulkInsertId => "_bulk_insert_id"; protected abstract string AddTableCopyBulkInsertId { get; } @@ -144,7 +147,15 @@ private async Task PerformBulkInsertAsync( activity?.AddTag("tempTable", tempTableRequired); activity?.AddTag("synchronous", sync); + var sw = Stopwatch.StartNew(); await BulkInsert(sync, context, tableInfo, entities, tableName, columns, options, ctk); + sw.Stop(); + + if (logger != null) + { + Log.BulkInsertExecuted(logger, sw.ElapsedMilliseconds, tableName); + } + return tableName; } @@ -254,16 +265,17 @@ protected virtual Task DropTempTableAsync(bool sync, DbContext dbContext, string return Task.CompletedTask; } - protected static async Task ExecuteAsync( + protected async Task ExecuteAsync( bool sync, DbContext context, string query, CancellationToken ctk) { - var command = context.Database.GetDbConnection().CreateCommand(); + using var command = context.Database.GetDbConnection().CreateCommand(); command.Transaction = context.Database.CurrentTransaction!.GetDbTransaction(); command.CommandText = query; + var sw = Stopwatch.StartNew(); if (sync) { // ReSharper disable once MethodHasAsyncOverloadWithCancellation @@ -273,5 +285,11 @@ protected static async Task ExecuteAsync( { await command.ExecuteNonQueryAsync(ctk); } + sw.Stop(); + + if (logger != null) + { + Log.ExecutedDbCommand(logger, sw.ElapsedMilliseconds, query); + } } } diff --git a/src/PhenX.EntityFrameworkCore.BulkInsert/Log.cs b/src/PhenX.EntityFrameworkCore.BulkInsert/Log.cs index b66ebf3..a4d49a2 100644 --- a/src/PhenX.EntityFrameworkCore.BulkInsert/Log.cs +++ b/src/PhenX.EntityFrameworkCore.BulkInsert/Log.cs @@ -27,4 +27,16 @@ internal static partial class Log Level = LogLevel.Error, Message = "Failed to drop temporary table.")] public static partial void DropTemporaryTableFailed(ILogger logger, Exception exception); + + [LoggerMessage( + EventId = 1004, + Level = LogLevel.Information, + Message = "Executed BulkInsert ({ElapsedMs}ms) [DestinationTable='{DestinationTable}']")] + public static partial void BulkInsertExecuted(ILogger logger, long elapsedMs, string destinationTable); + + [LoggerMessage( + EventId = 1005, + Level = LogLevel.Debug, + Message = "Executed DbCommand ({ElapsedMs}ms)\n{CommandText}")] + public static partial void ExecutedDbCommand(ILogger logger, long elapsedMs, string commandText); } diff --git a/tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/CapturingLogger.cs b/tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/CapturingLogger.cs new file mode 100644 index 0000000..44fc765 --- /dev/null +++ b/tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/CapturingLogger.cs @@ -0,0 +1,41 @@ +using Microsoft.Extensions.Logging; + +namespace PhenX.EntityFrameworkCore.BulkInsert.Tests.Tests.Logging; + +internal sealed record LogEntry(LogLevel Level, EventId EventId, string Message); + +internal sealed class CapturingLogger : ILogger +{ + private readonly List _entries; + + public CapturingLogger(List entries) + { + _entries = entries; + } + + public IDisposable? BeginScope(TState state) where TState : notnull => NullScope.Instance; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + _entries.Add(new LogEntry(logLevel, eventId, formatter(state, exception))); + } + + private sealed class NullScope : IDisposable + { + public static readonly NullScope Instance = new(); + public void Dispose() { } + } +} + +internal sealed class CapturingLoggerProvider(List entries) : ILoggerProvider +{ + public ILogger CreateLogger(string categoryName) => new CapturingLogger(entries); + public void Dispose() { } +} diff --git a/tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/LoggingTests.cs b/tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/LoggingTests.cs new file mode 100644 index 0000000..7dc26a1 --- /dev/null +++ b/tests/PhenX.EntityFrameworkCore.BulkInsert.Tests/Tests/Logging/LoggingTests.cs @@ -0,0 +1,132 @@ +using FluentAssertions; + +using Microsoft.Data.Sqlite; +using Microsoft.EntityFrameworkCore; +using Microsoft.Extensions.Logging; + +using PhenX.EntityFrameworkCore.BulkInsert.Extensions; +using PhenX.EntityFrameworkCore.BulkInsert.Sqlite; +using PhenX.EntityFrameworkCore.BulkInsert.Tests.DbContext; + +using Xunit; + +namespace PhenX.EntityFrameworkCore.BulkInsert.Tests.Tests.Logging; + +[Trait("Category", "Sqlite")] +public class LoggingTests +{ + [Fact] + public async Task BulkInsert_LogsBulkInsertExecuted_AtInformationLevel() + { + // Arrange + var logEntries = new List(); + using var loggerFactory = LoggerFactory.Create(builder => + builder + .AddProvider(new CapturingLoggerProvider(logEntries)) + .SetMinimumLevel(LogLevel.Debug)); + + await using var connection = new SqliteConnection("DataSource=:memory:"); + await connection.OpenAsync(); + + await using var context = new TestDbContextSqlite + { + ConfigureOptions = builder => builder + .UseSqlite(connection) + .UseLoggerFactory(loggerFactory) + .UseBulkInsertSqlite(), + }; + await context.Database.EnsureCreatedAsync(); + + var run = Guid.NewGuid(); + var entities = new List + { + new TestEntity { TestRun = run, Name = "Entity1" }, + new TestEntity { TestRun = run, Name = "Entity2" }, + }; + + // Act + await context.ExecuteBulkInsertAsync(entities); + + // Assert + logEntries.Should().Contain(e => + e.Level == LogLevel.Information && + e.EventId.Id == 1004 && + e.Message.Contains("Executed BulkInsert")); + } + + [Fact] + public async Task BulkInsert_LogsDbCommands_AtDebugLevel() + { + // Arrange + var logEntries = new List(); + using var loggerFactory = LoggerFactory.Create(builder => + builder + .AddProvider(new CapturingLoggerProvider(logEntries)) + .SetMinimumLevel(LogLevel.Debug)); + + await using var connection = new SqliteConnection("DataSource=:memory:"); + await connection.OpenAsync(); + + await using var context = new TestDbContextSqlite + { + ConfigureOptions = builder => builder + .UseSqlite(connection) + .UseLoggerFactory(loggerFactory) + .UseBulkInsertSqlite(), + }; + await context.Database.EnsureCreatedAsync(); + + var run = Guid.NewGuid(); + var entities = new List + { + new TestEntity { TestRun = run, Name = "Entity1" }, + }; + + // Act - ReturnEntities always uses a temp table, triggering auxiliary SQL commands + await context.ExecuteBulkInsertReturnEntitiesAsync(entities); + + // Assert + logEntries.Should().Contain(e => + e.Level == LogLevel.Debug && + e.EventId.Id == 1005 && + e.Message.Contains("Executed DbCommand")); + } + + [Fact] + public async Task BulkInsert_LogMessageContainsTableName() + { + // Arrange + var logEntries = new List(); + using var loggerFactory = LoggerFactory.Create(builder => + builder + .AddProvider(new CapturingLoggerProvider(logEntries)) + .SetMinimumLevel(LogLevel.Information)); + + await using var connection = new SqliteConnection("DataSource=:memory:"); + await connection.OpenAsync(); + + await using var context = new TestDbContextSqlite + { + ConfigureOptions = builder => builder + .UseSqlite(connection) + .UseLoggerFactory(loggerFactory) + .UseBulkInsertSqlite(), + }; + await context.Database.EnsureCreatedAsync(); + + var run = Guid.NewGuid(); + var entities = new List + { + new TestEntity { TestRun = run, Name = "Entity1" }, + }; + + // Act + await context.ExecuteBulkInsertAsync(entities); + + // Assert + logEntries.Should().Contain(e => + e.Level == LogLevel.Information && + e.EventId.Id == 1004 && + e.Message.Contains("test_entity")); + } +}