Add EF Core-style logging for bulk insert operations (#103)

Copilot · PhenX · web-flow · commit 03e36194746e · 2026-05-24T17:11:30.000+02:00
* Initial plan * Add logging similar to EF Core: BulkInsertExecuted and ExecutedDbCommand log messages Agent-Logs-Url: https://github.com/PhenX/PhenX.EntityFrameworkCore.BulkInsert/sessions/481b78be-69b9-450e-b8b4-3c7176838952 Co-authored-by: PhenX <42170+PhenX@users.noreply.github.com> * Apply review fixes for logging and resource disposal Agent-Logs-Url: https://github.com/PhenX/PhenX.EntityFrameworkCore.BulkInsert/sessions/50f8adc9-2589-4b71-a87e-14db3ec99af9 Co-authored-by: PhenX <42170+PhenX@users.noreply.github.com> * Update docs and Copilot instructions for logging changes Agent-Logs-Url: https://github.com/PhenX/PhenX.EntityFrameworkCore.BulkInsert/sessions/056ca3a1-0d57-424f-a270-daf8457b20bd Co-authored-by: PhenX <42170+PhenX@users.noreply.github.com> --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: PhenX <42170+PhenX@users.noreply.github.com>
diff --git 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
@@ -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<MyDbContext>(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
@@ -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<MyDbContext>(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
@@ -12,7 +12,7 @@
 namespace PhenX.EntityFrameworkCore.BulkInsert.MySql;
 
 [UsedImplicitly]
-internal class MySqlBulkInsertProvider(ILogger<MySqlBulkInsertProvider> logger) : BulkInsertProviderBase<MySqlServerDialectBuilder, MySqlBulkInsertOptions>(logger)
+internal class MySqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<MySqlServerDialectBuilder, MySqlBulkInsertOptions>(loggerFactory)
 {
     //language=sql
     /// <inheritdoc />
diff --git 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<OracleBulkInsertProvider>? logger) : BulkInsertProviderBase<OracleDialectBuilder, OracleBulkInsertOptions>(logger)
+internal class OracleBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<OracleDialectBuilder, OracleBulkInsertOptions>(loggerFactory)
 {
     /// <inheritdoc />
     protected override string BulkInsertId => "ROWID";
diff --git 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<PostgreSqlBulkInsertProvider>? logger) : BulkInsertProviderBase<PostgreSqlDialectBuilder, PostgreSqlBulkInsertOptions>(logger)
+internal class PostgreSqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<PostgreSqlDialectBuilder, PostgreSqlBulkInsertOptions>(loggerFactory)
 {
     //language=sql
     /// <inheritdoc />
diff --git 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<SqlServerBulkInsertProvider>? logger) : BulkInsertProviderBase<SqlServerDialectBuilder, SqlServerBulkInsertOptions>(logger)
+internal class SqlServerBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<SqlServerDialectBuilder, SqlServerBulkInsertOptions>(loggerFactory)
 {
     //language=sql
     /// <inheritdoc />
diff --git 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<SqliteBulkInsertProvider>? logger) : BulkInsertProviderBase<SqliteDialectBuilder, BulkInsertOptions>(logger)
+internal class SqliteBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<SqliteDialectBuilder, BulkInsertOptions>(loggerFactory)
 {
     private const int MaxParams = 1000;
 
diff --git 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<IBulkInsertProvider, TProvider>();
+        services.TryAddSingleton<ILoggerFactory, NullLoggerFactory>();
+        services.AddScoped<IBulkInsertProvider, TProvider>();
     }
 
     public void Validate(IDbContextOptions options)
diff --git 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<TDialect, TOptions>(ILogger? logger) : BulkInsertProviderUntyped<TDialect, TOptions>
+internal abstract class BulkInsertProviderBase<TDialect, TOptions>(ILoggerFactory? loggerFactory) : BulkInsertProviderUntyped<TDialect, TOptions>
     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<string> PerformBulkInsertAsync<T>(
         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
@@ -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
@@ -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<LogEntry> _entries;
+
+    public CapturingLogger(List<LogEntry> entries)
+    {
+        _entries = entries;
+    }
+
+    public IDisposable? BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
+
+    public bool IsEnabled(LogLevel logLevel) => true;
+
+    public void Log<TState>(
+        LogLevel logLevel,
+        EventId eventId,
+        TState state,
+        Exception? exception,
+        Func<TState, Exception?, string> 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<LogEntry> 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
@@ -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<LogEntry>();
+        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<TestEntity>
+        {
+            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<LogEntry>();
+        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<TestEntity>
+        {
+            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<LogEntry>();
+        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<TestEntity>
+        {
+            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"));
+    }
+}

Original file line number	Diff line number	Diff line change
`@@ -12,7 +12,7 @@`
`12`	`12`	`namespace PhenX.EntityFrameworkCore.BulkInsert.MySql;`
`13`	`13`
`14`	`14`	`[UsedImplicitly]`
`15`		`-internal class MySqlBulkInsertProvider(ILogger<MySqlBulkInsertProvider> logger) : BulkInsertProviderBase<MySqlServerDialectBuilder, MySqlBulkInsertOptions>(logger)`
	`15`	`+internal class MySqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<MySqlServerDialectBuilder, MySqlBulkInsertOptions>(loggerFactory)`
`16`	`16`	`{`
`17`	`17`	`//language=sql`
`18`	`18`	`/// <inheritdoc />`
Original file line number	Diff line number	Diff line change
`@@ -11,7 +11,7 @@`
`11`	`11`	`namespace PhenX.EntityFrameworkCore.BulkInsert.Oracle;`
`12`	`12`
`13`	`13`	`[UsedImplicitly]`
`14`		`-internal class OracleBulkInsertProvider(ILogger<OracleBulkInsertProvider>? logger) : BulkInsertProviderBase<OracleDialectBuilder, OracleBulkInsertOptions>(logger)`
	`14`	`+internal class OracleBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<OracleDialectBuilder, OracleBulkInsertOptions>(loggerFactory)`
`15`	`15`	`{`
`16`	`16`	`/// <inheritdoc />`
`17`	`17`	`protected override string BulkInsertId => "ROWID";`
Original file line number	Diff line number	Diff line change
`@@ -15,7 +15,7 @@`
`15`	`15`	`namespace PhenX.EntityFrameworkCore.BulkInsert.PostgreSql;`
`16`	`16`
`17`	`17`	`[UsedImplicitly]`
`18`		`-internal class PostgreSqlBulkInsertProvider(ILogger<PostgreSqlBulkInsertProvider>? logger) : BulkInsertProviderBase<PostgreSqlDialectBuilder, PostgreSqlBulkInsertOptions>(logger)`
	`18`	`+internal class PostgreSqlBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<PostgreSqlDialectBuilder, PostgreSqlBulkInsertOptions>(loggerFactory)`
`19`	`19`	`{`
`20`	`20`	`//language=sql`
`21`	`21`	`/// <inheritdoc />`
Original file line number	Diff line number	Diff line change
`@@ -10,7 +10,7 @@`
`10`	`10`	`namespace PhenX.EntityFrameworkCore.BulkInsert.SqlServer;`
`11`	`11`
`12`	`12`	`[UsedImplicitly]`
`13`		`-internal class SqlServerBulkInsertProvider(ILogger<SqlServerBulkInsertProvider>? logger) : BulkInsertProviderBase<SqlServerDialectBuilder, SqlServerBulkInsertOptions>(logger)`
	`13`	`+internal class SqlServerBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<SqlServerDialectBuilder, SqlServerBulkInsertOptions>(loggerFactory)`
`14`	`14`	`{`
`15`	`15`	`//language=sql`
`16`	`16`	`/// <inheritdoc />`
Original file line number	Diff line number	Diff line change
`@@ -13,7 +13,7 @@`
`13`	`13`	`namespace PhenX.EntityFrameworkCore.BulkInsert.Sqlite;`
`14`	`14`
`15`	`15`	`[UsedImplicitly]`
`16`		`-internal class SqliteBulkInsertProvider(ILogger<SqliteBulkInsertProvider>? logger) : BulkInsertProviderBase<SqliteDialectBuilder, BulkInsertOptions>(logger)`
	`16`	`+internal class SqliteBulkInsertProvider(ILoggerFactory? loggerFactory) : BulkInsertProviderBase<SqliteDialectBuilder, BulkInsertOptions>(loggerFactory)`
`17`	`17`	`{`
`18`	`18`	`private const int MaxParams = 1000;`
`19`	`19`
Original file line number	Diff line number	Diff line change
`@@ -16,8 +16,8 @@ public DbContextOptionsExtensionInfo Info`
`16`	`16`
`17`	`17`	`public void ApplyServices(IServiceCollection services)`
`18`	`18`	`{`
`19`		`- services.TryAddSingleton(typeof(ILogger<>), typeof(NullLogger<>));`
`20`		`- services.AddSingleton<IBulkInsertProvider, TProvider>();`
	`19`	`+ services.TryAddSingleton<ILoggerFactory, NullLoggerFactory>();`
	`20`	`+ services.AddScoped<IBulkInsertProvider, TProvider>();`
`21`	`21`	`}`
`22`	`22`
`23`	`23`	`public void Validate(IDbContextOptions options)`