Logging, Interceptors and Diagnostics

using System.Data.Common;
using System.Security.Claims;
using Microsoft.EntityFrameworkCore;
using Microsoft.EntityFrameworkCore.Diagnostics;

var builder = WebApplication.CreateBuilder(args);

builder.Services.AddHttpContextAccessor();
builder.Services.AddSingleton(TimeProvider.System);
builder.Services.AddSingleton<AuditInterceptor>();
builder.Services.AddSingleton<SlowCommandInterceptor>();

builder.Services.AddDbContext<ShopDb>((sp, options) =>
{
    options.UseNpgsql(builder.Configuration.GetConnectionString("Shop"))
        .AddInterceptors(
            sp.GetRequiredService<AuditInterceptor>(),
            sp.GetRequiredService<SlowCommandInterceptor>());

    if (builder.Environment.IsDevelopment())
    {
        options.EnableSensitiveDataLogging().EnableDetailedErrors();
    }
});

var app = builder.Build();

app.MapPost("/customers", async (NewCustomer body, ShopDb db, CancellationToken ct) =>
{
    var customer = new Customer { Email = body.Email, Name = body.Name };
    db.Customers.Add(customer);
    await db.SaveChangesAsync(ct);
    return TypedResults.Created($"/customers/{customer.Id}", new { customer.Id, customer.CreatedAt });
});

app.Run();

public record NewCustomer(string Email, string Name);

public interface IAudited
{
    DateTimeOffset CreatedAt { get; set; }
    DateTimeOffset UpdatedAt { get; set; }
    string UpdatedBy { get; set; }
}

public class Customer : IAudited
{
    public int Id { get; set; }
    public string Email { get; set; } = "";
    public string Name { get; set; } = "";
    public DateTimeOffset CreatedAt { get; set; }
    public DateTimeOffset UpdatedAt { get; set; }
    public string UpdatedBy { get; set; } = "";
}

public sealed class AuditInterceptor(TimeProvider clock, IHttpContextAccessor http) : SaveChangesInterceptor
{
    public override InterceptionResult<int> SavingChanges(DbContextEventData eventData, InterceptionResult<int> result)
    {
        Stamp(eventData.Context);
        return result;
    }

    public override ValueTask<InterceptionResult<int>> SavingChangesAsync(
        DbContextEventData eventData, InterceptionResult<int> result, CancellationToken cancellationToken = default)
    {
        Stamp(eventData.Context);
        return ValueTask.FromResult(result);
    }

    private void Stamp(DbContext? context)
    {
        if (context is null) return;
        var now = clock.GetUtcNow();
        var user = http.HttpContext?.User.FindFirstValue(ClaimTypes.NameIdentifier) ?? "system";

        foreach (var entry in context.ChangeTracker.Entries<IAudited>())
        {
            if (entry.State == EntityState.Added)
            {
                entry.Entity.CreatedAt = now;
            }
            else if (entry.State == EntityState.Modified)
            {
                // A client cannot rewrite history by sending a different CreatedAt.
                entry.Property(e => e.CreatedAt).IsModified = false;
            }
            else
            {
                continue;
            }
            entry.Entity.UpdatedAt = now;
            entry.Entity.UpdatedBy = user;
        }
    }
}

public sealed partial class SlowCommandInterceptor(ILogger<SlowCommandInterceptor> logger) : DbCommandInterceptor
{
    private static readonly TimeSpan Threshold = TimeSpan.FromMilliseconds(500);

    public override DbDataReader ReaderExecuted(DbCommand command, CommandExecutedEventData eventData, DbDataReader result)
    {
        Check(command, eventData);
        return result;
    }

    public override ValueTask<DbDataReader> ReaderExecutedAsync(
        DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default)
    {
        Check(command, eventData);
        return ValueTask.FromResult(result);
    }

    // ExecuteUpdate, ExecuteDelete and ExecuteSql run as non-queries; aggregates can run as scalars.
    public override int NonQueryExecuted(DbCommand command, CommandExecutedEventData eventData, int result)
    {
        Check(command, eventData);
        return result;
    }

    public override ValueTask<int> NonQueryExecutedAsync(
        DbCommand command, CommandExecutedEventData eventData, int result, CancellationToken cancellationToken = default)
    {
        Check(command, eventData);
        return ValueTask.FromResult(result);
    }

    public override object? ScalarExecuted(DbCommand command, CommandExecutedEventData eventData, object? result)
    {
        Check(command, eventData);
        return result;
    }

    public override ValueTask<object?> ScalarExecutedAsync(
        DbCommand command, CommandExecutedEventData eventData, object? result, CancellationToken cancellationToken = default)
    {
        Check(command, eventData);
        return ValueTask.FromResult(result);
    }

    private void Check(DbCommand command, CommandExecutedEventData eventData)
    {
        if (eventData.Duration > Threshold)
        {
            // CommandText only: parameter values stay out of the log.
            LogSlowCommand(logger, eventData.Duration.TotalMilliseconds, command.CommandText);
        }
    }

    [LoggerMessage(Level = LogLevel.Warning, Message = "Slow SQL command took {ElapsedMs} ms: {CommandText}")]
    private static partial void LogSlowCommand(ILogger logger, double elapsedMs, string commandText);
}

public class ShopDb(DbContextOptions<ShopDb> options) : DbContext(options)
{
    public DbSet<Customer> Customers => Set<Customer>();
}