Add query logging

src/Shiny.Extensions.EntityFramework/Auditing/AuditSaveChangesInterceptor.cs

@@ -5,7 +5,7 @@ namespace Shiny.Auditing;
 
 // TODO: I need the entity ID after insert
 // TODO: catch ExecuteUpdate & ExecuteDelete - how?  ExecuteDelete isn't something I believe in with audited tables anyhow - So only ExecuteUpdate
-public class AuditSaveChangesInterceptor(IAuditInfoProvider provider) : SaveChangesInterceptor
+public class AuditSaveChangesInterceptor(IContextInfoProvider provider) : SaveChangesInterceptor
 {
     AuditScope? auditScope;
 

src/Shiny.Extensions.EntityFramework/Auditing/AuditScope.cs

@@ -19,7 +19,7 @@ public class AuditScope
     }
 
 
-    public static AuditScope Create(IAuditInfoProvider provider, DbContextEventData eventData)
+    public static AuditScope Create(IContextInfoProvider provider, DbContextEventData eventData)
     {
         var state = AuditScope.BuildState(provider, eventData);
         var scope = new AuditScope(eventData.Context!, state);
@@ -86,7 +86,7 @@ static DbOperation ToOperation(EntityState state)
     }
 
 
-    static List<EntityAuditContext> BuildState(IAuditInfoProvider provider, DbContextEventData eventData)
+    static List<EntityAuditContext> BuildState(IContextInfoProvider provider, DbContextEventData eventData)
     {
         var entries = new List<EntityAuditContext>();
         var changeTracker = eventData.Context!.ChangeTracker;

src/Shiny.Extensions.EntityFramework/EntityFrameworkExtensions.cs

@@ -1,12 +1,61 @@
 using System.Linq;
 using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.DependencyInjection;
 using Shiny.Auditing;
+using Shiny.QueryLog;
 
 namespace Shiny;
 
 
 public static class EntityFrameworkExtensions
 {
+    public static IServiceCollection AddDbContextAuditing<T>(this IServiceCollection services) where T : class, IContextInfoProvider
+    {
+        services.AddScoped<T>();
+        services.AddScoped<AuditSaveChangesInterceptor>();
+        return services;
+    }
+
+
+    public static IServiceCollection AddDbContextAuditing(
+        this IServiceCollection services,
+        IContextInfoProvider contextProvider
+    ) => services.AddScoped(_ => new AuditSaveChangesInterceptor(contextProvider));
+
+
+    public static DbContextOptionsBuilder UseAuditing(this DbContextOptionsBuilder builder, IServiceProvider scope)
+    {
+        var interceptor = scope.GetRequiredService<AuditSaveChangesInterceptor>();
+        return builder.AddInterceptors(interceptor);
+    }
+
+
+    public static IServiceCollection AddDbContextQueryLogging<T>(this IServiceCollection services, TimeSpan minLogDuration) where T : class, IContextInfoProvider
+    {
+        services.AddScoped<T>();
+        services.AddScoped(sp =>
+        {
+            var contextInfo = sp.GetRequiredService<T>();
+            return new QueryLogDbCommandInterceptor(contextInfo, minLogDuration);
+        });
+        return services;
+    }
+
+
+    public static IServiceCollection AddDbContextQueryLogging(
+        this IServiceCollection services,
+        IContextInfoProvider contextProvider,
+        TimeSpan minLogDuration
+    ) => services.AddScoped(_ => new QueryLogDbCommandInterceptor(contextProvider, minLogDuration));
+
+
+    public static void UseQueryLogging(this DbContextOptionsBuilder builder, IServiceProvider scope)
+    {
+        var interceptor = scope.GetRequiredService<QueryLogDbCommandInterceptor>();
+        builder.AddInterceptors(interceptor);
+    } 
+
+
     public static ModelConfigurationBuilder SetDefaultStringLength(this ModelConfigurationBuilder configurationBuilder, int length = 50, bool unicode = true)
     {
         configurationBuilder
@@ -46,7 +95,25 @@ public static ModelBuilder MapAuditing(this ModelBuilder modelBuilder)
         map.Property(x => x.AppLocation).HasMaxLength(1024);
 
         return modelBuilder;
-    }    
+    }   
+
+
+    public static ModelBuilder MapSlowQueryAuditing(this ModelBuilder modelBuilder)
+    {
+        var map = modelBuilder.Entity<QueryLogEntry>();
+
+        map.HasKey(x => x.Id);
+        map.Property(x => x.Id).ValueGeneratedOnAdd();
+        map.Property(x => x.Query).HasMaxLength(5000);
+        map.Property(x => x.Duration);
+        map.Property(x => x.Timestamp);
+
+        map.Property(x => x.UserIdentifier).HasMaxLength(50);
+        map.Property(x => x.UserIpAddress).HasMaxLength(39);
+        map.Property(x => x.AppLocation).HasMaxLength(1024);
+
+        return modelBuilder;
+    }  
 
 
     public static ModelBuilder MapEasyPropertyIds(this ModelBuilder modelBuilder)

src/Shiny.Extensions.EntityFramework/Auditing/IAuditInfoProvider.cs → src/Shiny.Extensions.EntityFramework/IContextInfoProvider.cs

@@ -1,6 +1,6 @@
-namespace Shiny.Auditing;
+namespace Shiny;
 
-public interface IAuditInfoProvider
+public interface IContextInfoProvider
 {
     /// <summary>
     /// Can be a URL or anything else if available

src/Shiny.Extensions.EntityFramework/QueryLog/QueryLogDbCommandInterceptor.cs

@@ -0,0 +1,56 @@
+using System.Data.Common;
+using Microsoft.EntityFrameworkCore.Diagnostics;
+
+namespace Shiny.QueryLog;
+
+
+public class QueryLogDbCommandInterceptor(IContextInfoProvider infoProvider, TimeSpan minLogDuration) : IDbCommandInterceptor
+{
+    public int NonQueryExecuted(DbCommand command, CommandExecutedEventData eventData, int result)
+    {
+        this.TryLog(command, eventData);
+        return result;
+    }
+
+
+    public DbDataReader ReaderExecuted(DbCommand command, CommandExecutedEventData eventData, DbDataReader result)
+    {
+        this.TryLog(command, eventData);
+        return result;
+    }
+
+
+    public object? ScalarExecuted(DbCommand command, CommandExecutedEventData eventData, object? result)
+    {
+        this.TryLog(command, eventData);
+        return result;
+    }
+
+
+    protected void TryLog(DbCommand command, CommandExecutedEventData eventData)
+    {
+        if (minLogDuration < eventData.Duration)
+        {
+            var log = new QueryLogEntry
+            {
+                UserIdentifier = infoProvider.UserIdentifier,
+                UserIpAddress = infoProvider.UserIpAddress,
+                AppLocation = infoProvider.AppLocation,
+
+                Query = eventData.Command.CommandText,
+                Duration = eventData.Duration,
+                Timestamp = DateTimeOffset.UtcNow
+            };
+            try
+            {
+                // TODO: cannot audit seeding/migrations data
+                eventData.Context!.Add(log);
+                eventData.Context.SaveChanges();
+            }
+            catch (Exception ex)
+            {
+                Console.WriteLine(ex.ToString());
+            }
+        }        
+    }
+}

src/Shiny.Extensions.EntityFramework/QueryLog/QueryLogEntry.cs

@@ -0,0 +1,13 @@
+namespace Shiny.QueryLog;
+
+public class QueryLogEntry
+{
+    public int Id { get; set; }
+    public string Query { get; set; }
+    public TimeSpan Duration { get; set; }
+    public DateTimeOffset Timestamp { get; set; }
+
+    public string? UserIdentifier { get; set; }
+    public string? AppLocation { get; set; }
+    public string? UserIpAddress { get; set; }
+}

tests/Shiny.Extensions.EntityFramework.Tests/AuditTests.cs → tests/Shiny.Extensions.EntityFramework.Tests/EfTests.Auditing.cs

@@ -1,50 +1,14 @@
 using FluentAssertions;
 using Microsoft.EntityFrameworkCore;
-using Microsoft.Extensions.DependencyInjection;
-using Npgsql;
 using Shiny.Auditing;
 
 namespace Shiny.Extensions.EntityFramework.Tests;
 
 
 // TODO: check entityId & entityType
-public class AuditTests : IDisposable
+public partial class EfTests
 {
-    readonly TestAuditInfoProvider auditProvider;
-    readonly IServiceProvider serviceProvider;
 
-    public AuditTests()
-    {
-        this.auditProvider = new();
-
-        var services = new ServiceCollection();
-        services.AddSingleton<IAuditInfoProvider>(this.auditProvider);
-        services.AddScoped<AuditSaveChangesInterceptor>();
-        services.AddDbContext<TestDbContext>((sp, opts) =>
-        {
-            // .UseSqlite("Data Source=test.db")
-            opts.UseNpgsql(new NpgsqlDataSourceBuilder("User ID=sa;Password=Blargh911!;Host=localhost;Port=5432;Database=AuditUnitTests;Pooling=true;Connection Lifetime=30;").Build());
-            var interceptor = sp.GetRequiredService<AuditSaveChangesInterceptor>();
-            opts.AddInterceptors(interceptor);
-        });
-        this.serviceProvider = services.BuildServiceProvider();
-
-        using var scope = this.serviceProvider.CreateScope();
-        var data = scope.ServiceProvider.GetRequiredService<TestDbContext>();
-        data.Database.EnsureDeleted();
-        data.Database.EnsureCreated();
-
-        // TODO: seed
-    }
-
-    async Task DoDb(Func<TestDbContext, Task> task)
-    {
-        using var scope = this.serviceProvider.CreateScope();
-        var data = scope.ServiceProvider.GetRequiredService<TestDbContext>();
-        await task(data);
-    }
-
-
     [Fact]
     public async Task AddAudits()
     {
@@ -106,6 +70,15 @@ await this.DoDb(async data =>
     }
 
 
+    void AssertAudit(AuditEntry audit, DbOperation op)
+    {
+        audit.Operation.Should().Be(op, "Invalid Operation");
+        audit.UserIdentifier.Should().Be("Test User");
+        audit.UserIpAddress.Should().Be("0.0.0.0");
+        audit.AppLocation.Should().Be("UNIT TESTS");
+    }
+
+
     Task Seed() => this.DoDb(data =>
     {
         var manu = new Manufacturer { Name = "Cadillac" };
@@ -119,23 +92,4 @@ Task Seed() => this.DoDb(data =>
         data.Add(model);
         return data.SaveChangesAsync();
     });
-
-
-    void AssertAudit(AuditEntry audit, DbOperation op)
-    {
-        audit.Operation.Should().Be(op, "Invalid Operation");
-        audit.UserIdentifier.Should().Be("Test User");
-        audit.UserIpAddress.Should().Be("0.0.0.0");
-        audit.AppLocation.Should().Be("UNIT TESTS");
-    }
-
-    public void Dispose() => (this.serviceProvider as IDisposable)?.Dispose();
-}
-
-public class TestAuditInfoProvider : IAuditInfoProvider
-{
-    public string? AppLocation { get; set; } = "UNIT TESTS";
-    public string? Tenant { get; set; } = "Test Tenant";
-    public string? UserIdentifier { get; set; } = "Test User";
-    public string? UserIpAddress { get; set; } = "0.0.0.0";
 }

tests/Shiny.Extensions.EntityFramework.Tests/EfTests.QueryLogs.cs

@@ -0,0 +1,23 @@
+using FluentAssertions;
+using Microsoft.EntityFrameworkCore;
+
+namespace Shiny.Extensions.EntityFramework.Tests;
+
+public partial class EfTests
+{
+
+    [Fact]
+    public async Task DidLog()
+    {
+        await this.DoDb(async data =>
+        {
+            await data.Manufacturers.ToListAsync();
+        });
+
+        await this.DoDb(async data =>
+        {
+            var logs = await data.QueryLogs.ToListAsync();
+            logs.Count.Should().BeGreaterOrEqualTo(1, "No query logs");
+        });
+    }
+}

tests/Shiny.Extensions.EntityFramework.Tests/EfTests.cs

@@ -0,0 +1,54 @@
+using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.DependencyInjection;
+using Npgsql;
+
+namespace Shiny.Extensions.EntityFramework.Tests;
+
+
+public partial class EfTests : IDisposable
+{
+    readonly TestContextInfoProvider contextProvider;
+    readonly IServiceProvider serviceProvider;
+
+    public EfTests()
+    {
+        this.contextProvider = new();
+
+        var services = new ServiceCollection();
+        services.AddDbContextAuditing(this.contextProvider);
+        services.AddDbContextQueryLogging(this.contextProvider, TimeSpan.Zero);
+
+        services.AddDbContext<TestDbContext>((sp, opts) => opts
+            .UseNpgsql(new NpgsqlDataSourceBuilder("User ID=sa;Password=Blargh911!;Host=localhost;Port=5432;Database=AuditUnitTests;Pooling=true;Connection Lifetime=30;").Build())
+            .UseAuditing(sp)
+            .UseQueryLogging(sp)
+            // .UseSqlite("Data Source=test.db")
+        );
+        this.serviceProvider = services.BuildServiceProvider();
+
+        using var scope = this.serviceProvider.CreateScope();
+        var data = scope.ServiceProvider.GetRequiredService<TestDbContext>();
+        data.Database.EnsureDeleted();
+        data.Database.EnsureCreated();
+
+        // TODO: seed
+    }
+
+    async Task DoDb(Func<TestDbContext, Task> task)
+    {
+        using var scope = this.serviceProvider.CreateScope();
+        var data = scope.ServiceProvider.GetRequiredService<TestDbContext>();
+        await task(data);
+    }
+
+
+    public void Dispose() => (this.serviceProvider as IDisposable)?.Dispose();
+}
+
+public class TestContextInfoProvider : IContextInfoProvider
+{
+    public string? AppLocation { get; set; } = "UNIT TESTS";
+    public string? Tenant { get; set; } = "Test Tenant";
+    public string? UserIdentifier { get; set; } = "Test User";
+    public string? UserIpAddress { get; set; } = "0.0.0.0";
+}

tests/Shiny.Extensions.EntityFramework.Tests/TestDbContext.cs

@@ -1,12 +1,15 @@
 using System.Text.Json;
 using Microsoft.EntityFrameworkCore;
+using Microsoft.EntityFrameworkCore.Infrastructure;
 using Shiny.Auditing;
+using Shiny.QueryLog;
 
 namespace Shiny.Extensions.EntityFramework.Tests;
 
 public class TestDbContext(DbContextOptions<TestDbContext> options) : DbContext(options)
 {
     public DbSet<AuditEntry> AuditEntries => this.Set<AuditEntry>();
+    public DbSet<QueryLogEntry> QueryLogs => this.Set<QueryLogEntry>();
     public DbSet<Manufacturer> Manufacturers => this.Set<Manufacturer>();
     public DbSet<Model> Models => this.Set<Model>();