Entity Framework Core中的日志记录与拦截器

Posted JimCarter

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Entity Framework Core中的日志记录与拦截器相关的知识，希望对你有一定的参考价值。

https://docs.microsoft.com/zh-cn/ef/core/logging-events-diagnostics/

文章目录

1.机制

efcore包含一些用于生成日志、响应时间和或者诊断结果的机制。具体见下表：

机制名称支持异步范围进行配置的位置用途
简单的日志记录否上下文数据库上下文开发时日志记录
Microsoft.Extensions.Logging否上下文DI或数据库上下文生产日志记录
事件否上下文任何位置对 EF 事件做出反应
拦截器是上下文数据库上下文进行 EF 操作
诊断侦听器否进程全局应用程序诊断

2. 简单的日志记录

直接在OnConfiguring里配置LogTo即可：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
{
    optionsBuilder.LogTo(Console.WriteLine);
    //或
    optionsBuilder.LogTo(msg=>Console.WriteLine(msg));
}

2.1 日志的详细信息

默认efcore不会将数据的值包含在异常消息中，因为这类数据可能是敏感的。但是在调试时如果能够看到这些值将是非常非常有用的，通过EnableSensitiveDataLogging()启用此功能:

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine)
        .EnableSensitiveDataLogging();

出于性能方面的考虑，efcore不会将每一次对数据库的调用都用try-catch包裹起来。但这样有时候遇到问题时会很难诊断，特别是当数据库返回null值而模型却不允许null的时候。可以使用EnableDetailedErrors方法，让efcore返回具体的错误信息：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine)
        .EnableDetailedErrors();

2.2 日志过滤

  1. 通过LogTo的第二个参数控制日志级别：
protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(Console.WriteLine, LogLevel.Information);
  1. 将EventId（可从 CoreEventId 类或 RelationalEventId 类获取）传入LogTo的第二个参数，以输出指定类型的日志：
protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine, new[] { CoreEventId.ContextDisposed, CoreEventId.ContextInitialized });
  1. 也可以根据消息的类别进行过滤

每条日志消息都分配到一个命名的分层记录器类别。 类别为：

类别说明
Microsoft.EntityFrameworkCore所有 EF Core 消息
Microsoft.EntityFrameworkCore.Database所有数据库交互
Microsoft.EntityFrameworkCore.Database.Connection使用数据库连接
Microsoft.EntityFrameworkCore.Database.Command使用数据库命令
Microsoft.EntityFrameworkCore.Database.Transaction使用数据库事务
Microsoft.EntityFrameworkCore.Update保存实体，排除数据库交互
Microsoft.EntityFrameworkCore.Model所有模型和元数据交互
Microsoft.EntityFrameworkCore.Model.Validation模型验证
Microsoft.EntityFrameworkCore.Query查询，排除数据库交互
Microsoft.EntityFrameworkCore.Infrastructure常规事件，例如上下文创建
Microsoft.EntityFrameworkCore.Scaffolding数据库反向工程
Microsoft.EntityFrameworkCore.Migrations迁移
Microsoft.EntityFrameworkCore.ChangeTracking更改跟踪交互

比如记录数据库交互的日志：

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(Console.WriteLine, new[] { DbLoggerCategory.Database.Name });
  1. 自定义过滤器
protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder
        .LogTo(
            Console.WriteLine,
            (eventId, logLevel) => logLevel >= LogLevel.Information
                                   || eventId == RelationalEventId.ConnectionOpened
                                   || eventId == RelationalEventId.ConnectionClosed);

2.3 设置日志的内容和格式

默认日志内容是多行显示，第一行包括Loglevel、本地时间、EventId、消息类别，第二行是具体内容：

info: 10/6/2020 10:52:45.581 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      CREATE TABLE "Blogs" (
          "Id" INTEGER NOT NULL CONSTRAINT "PK_Blogs" PRIMARY KEY AUTOINCREMENT,
          "Name" INTEGER NOT NULL
      );
dbug: 10/6/2020 10:52:45.582 RelationalEventId.TransactionCommitting[20210] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committing transaction.
dbug: 10/6/2020 10:52:45.585 RelationalEventId.TransactionCommitted[20202] (Microsoft.EntityFrameworkCore.Database.Transaction)
      Committed transaction.

设置DbContextLoggerOptions.DefaultWithUtcTime使用UTC时间和单行显示

protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
    => optionsBuilder.LogTo(
        Console.WriteLine,
        LogLevel.Debug,
        DbContextLoggerOptions.UtcTime | DbContextLoggerOptions.SingleLine);

3. 使用Microsoft.Extensions.Logging

默认已支持

4. 事件

efcore包含有以下几个事件

事件引入的efcore版本触发时间
DbContext.SavingChanges5.0在调用SaveChanges或SaveChangesAsync前
DbContext.SavedChanges5.0成功调用SaveChanges 或 SaveChangesAsync之后
DbContext.SaveChangesFailed5.0调用SaveChanges 或 SaveChangesAsync失败时
ChangeTracker.Tracked2.1context首次跟踪实体后
ChangeTracker.StateChanged2.1当被跟踪的实体更改其状态时（首次进行跟踪时不会触发）

示例：

public interface IHasTimestamps
{
    DateTime? Added { get; set; }
    DateTime? Deleted { get; set; }
    DateTime? Modified { get; set; }
}
public BlogsContext()
{
    ChangeTracker.StateChanged += UpdateTimestamps;
    ChangeTracker.Tracked += UpdateTimestamps;
}

private static void UpdateTimestamps(object sender, EntityEntryEventArgs e)
{
    if (e.Entry.Entity is IHasTimestamps entityWithTimestamps)
    {
        switch (e.Entry.State)
        {
            case EntityState.Deleted:
                entityWithTimestamps.Deleted = DateTime.UtcNow;
                Console.WriteLine($"Stamped for delete: {e.Entry.Entity}");
                break;
            case EntityState.Modified:
                entityWithTimestamps.Modified = DateTime.UtcNow;
                Console.WriteLine($"Stamped for update: {e.Entry.Entity}");
                break;
            case EntityState.Added:
                entityWithTimestamps.Added = DateTime.UtcNow;
                Console.WriteLine($"Stamped for insert: {e.Entry.Entity}");
                break;
        }
    }
}

5. 拦截器

可以拦截、修改、禁止efcore的操作。包括低级的数据库操作（如执行命令）和高级的数据库操作（如对SaveChanges的调用）。

5.1 注册拦截器

在OnConfiguring里进行配置

public class ExampleContext : BlogsContext
{
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder.AddInterceptors(new TaggedQueryCommandInterceptor());
}

5.2 实现数据库拦截器

低级别的数据库拦截涉及到三个接口：

接口efcore自带实现基类已截获数据库操作
IDbCommandInterceptorDbCommandInterceptor创建命令 执行命令 执行失败
IDbConnectionInterceptorDbConnectionInterceptor打开/关闭连接 连接失败
IDbTransactionInterceptorDbTransactionInterceptor创建事务 提交事务 回退事务 创建和使用保存点 事务失败

然后使用TagWith方法对查询进行标记：

var blogs1 = context.Blogs.TagWith("Use hint: robust plan").ToList();

创建上面的TaggedQueryCommandInterceptor拦截器：

public class TaggedQueryCommandInterceptor : DbCommandInterceptor
{
    public override InterceptionResult<DbDataReader> ReaderExecuting(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result)
    {
        ManipulateCommand(command);
        return result;
    }

    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result,CancellationToken cancellationToken = default)
    {
        ManipulateCommand(command);
        return new ValueTask<InterceptionResult<DbDataReader>>(result);
    }

    private static void ManipulateCommand(DbCommand command)
    {
        if (command.CommandText.StartsWith("-- Use hint: robust plan", StringComparison.Ordinal))
        {
            command.CommandText += " OPTION (ROBUST PLAN)";
        }
    }
}

拦截器同时实现了同步和异步的方法，可应用到同步或异步查询中。此时生成的sql如下：

-- Use hint: robust plan

SELECT [b].[Id], [b].[Name]
FROM [Blogs] AS [b] OPTION (ROBUST PLAN)

5.2.1 示例

需要实现的功能：当查询前先查下缓存，如有有缓存则直接返回。否则将从数据库查询出来的数据存放到缓存中。

以下示例用来获取最新的每天消息：

  1. 首先给查询打tag：
async Task<string> GetDailyMessage(DailyMessageContext context)
    => (await context.DailyMessages.TagWith("Get_Daily_Message").OrderBy(e => e.Id).LastAsync()).Message;
  1. 设置拦截器需要的一些参数
public class CachingCommandInterceptor : DbCommandInterceptor
{
    private readonly object _lock = new object();
    private int _id;
    private string _message;
    private DateTime _queriedAt;
    
    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result,CancellationToken cancellationToken = default)
    {
       //...
    }

    public override async ValueTask<DbDataReader> ReaderExecutedAsync(DbCommand command,CommandExecutedEventData eventData,DbDataReader result,CancellationToken cancellationToken = default)
    {
        //...
    }
}

因为拦截器是全局的而且可以应用到多个dbcotext上，所以需要定义一个锁。
3. 在数据库查询执行之前，拦截器根据之前打的tag来定位具体的查询，然后检查是否有缓存

public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command,CommandEventData eventData,InterceptionResult<DbDataReader> result,CancellationToken cancellationToken = default)
{
    if (command.CommandText.StartsWith("-- Get_Daily_Message", StringComparison.Ordinal))
    {
        lock (_lock)
        {
            if (_message != null&& DateTime.UtcNow < _queriedAt + new TimeSpan(0, 0, 10))//查询10s以内的数据
            {
                //因为sql不会到数据库执行，所以可以加一些自定义的注释
                command.CommandText = "-- Get_Daily_Message: Skipping DB call; using cache.";
                result = InterceptionResult<DbDataReader>.SuppressWithResult(new CachedDailyMessageDataReader(_id, _message));
            }
        }
    }

    return new ValueTask<InterceptionResult<DbDataReader>>(result);
}
  1. 如果没有发现缓存则会执行到ReaderExecutedAsync方法
public override async ValueTask<DbDataReader> ReaderExecutedAsync(DbCommand command,CommandExecutedEventData eventData,DbDataReader result,CancellationToken cancellationToken = default)
{
    if (command.CommandText.StartsWith("-- Get_Daily_Message", StringComparison.Ordinal)&& !(result is CachedDailyMessageDataReader))
    {
        try
        {
            await result.ReadAsync(cancellationToken);
            lock (_lock)
            {
                _id = result.GetInt32(0);
                _message = result.GetString(1);
                _queriedAt = DateTime.UtcNow;
                return new CachedDailyMessageDataReader(_id, _message);
            }
        }
        finally
        {
            await result.DisposeAsync();
        }
    }

    return result;
}

5.3 对OnSaveChanges的拦截

应用场景：记录某些人对数据做了哪些更改时。

实现方法：有两个数据库上线文，用户对BlogsContext进行更改操作，并配置拦截。AuditContext存储用户的具体操作。

  1. 首先配置BlogsContext
public class BlogsContext : DbContext
{
    private readonly AuditingInterceptor _auditingInterceptor = new AuditingInterceptor("DataSource=audit.db");
    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder
            .AddInterceptors(_auditingInterceptor)
            .UseSqlite("DataSource=blogs.db");
    public DbSet<Blog> Blogs { get; set; }
}

主要是配置拦截器
2. AuditContext无须额外设置

public class AuditContext : DbContext
{
    private readonly string _connectionString;

    public AuditContext(string connectionString)
    {
        _connectionString = connectionString;
    }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder.UseSqlite(_connectionString);

    public DbSet<SaveChangesAudit> SaveChangesAudits { get; set; }
}

public class SaveChangesAudit
{
    public int Id { get; set; }
    public Guid AuditId { get; set; }
    public DateTime StartTime { get; set; }
    public DateTime EndTime { get; set; }
    public bool Succeeded { get; set; }
    public string ErrorMessage { get; set; }

    public ICollection<EntityAudit> Entities { get; } = new List<EntityAudit>();
}

public class EntityAudit
{
    public int Id { get; set; }
    public EntityState State { get; set; }
    public string AuditMessage { get; set; }

    public SaveChangesAudit SaveChangesAudit { get; set; }
}
  1. AuditingInterceptor的实现逻辑
    在SaveChanges时就记录数据，并写入数据库。如果保存失败，则记录操作失败。如果保存成功，则记录操作成功。

实现ISaveChangesInterceptor接口，实现SavingChangesAsync、SavedChangesAsync、SaveChangesFailedAsync三个异步方法和对应的同步方法。

//保存时
public async ValueTask<InterceptionResult<int>> SavingChangesAsync(
    DbContextEventData eventData,
    InterceptionResult<int> result,
    CancellationToken cancellationToken = default)
{
    _audit = CreateAudit(eventData.Context);

    using (var auditContext = new AuditContext(_connectionString))
    {
        auditContext.Add(_audit);
        await auditContext.SaveChangesAsync();
    }

    return result;
}
//保存成功时
public async ValueTask<int> SavedChangesAsync(
    SaveChangesCompletedEventData eventData,
    int result,
    CancellationToken cancellationToken = default)
{
    using (var auditContext = new AuditContext(_connectionString))
    {
        auditContext.Attach(_audit);
        _audit.Succeeded = true;
        _audit.EndTime = DateTime.UtcNow;

        await auditContext.SaveChangesAsync(cancellationToken);
    }

    return result;
}
//保存失败时
public async Task SaveChangesFailedAsync(
    DbContextErrorEventData eventData,
    CancellationToken cancellationToken = default)
{
    using (var auditContext = new AuditContext(_connectionString))
    {
        auditContext.Attach(_audit);
        _audit.Succeeded = false;
        _audit.EndTime = DateTime.UtcNow;
        _audit.ErrorMessage = eventData.Exception.InnerException?.Message;

        await auditContext.SaveChangesAsync(cancella
以上是关于Entity Framework Core中的日志记录与拦截器的主要内容，如果未能解决你的问题，请参考以下文章
 

 Entity Framework Core 中的日志记录与拦截器


 请问在 .NET Core 中如何让 Entity Framework Core 在日志中记录由 LINQ 生成的SQL语句？


 在 .NET Core 中如何让 Entity Framework Core 在日志中记录由 LINQ 生成的SQL语句


 EF6 System.Data.Entity.Core.EntityKey 在 Entity Framework Core 中的等价物是啥？


 Entity Framework Core 2.1 中的 ReverseEngineeringGenerator


 Entity Framework Core 2 中的 ConnectionString 生成器