c# - Entity Framework 记录重复项

Question

我们正在运行 Entity Framework 6 并有一个 DatabaseLogFormatter 来格式化我们的数据，它通过 NLog AsyncTargetWrapper 记录到一个文件中。该应用程序是一个 MVC5 网络应用程序。

DatabaseLogFormatter 大部分是空 stub ，除了 LogCommand 和 LogResult。两者都正确格式化数据。到目前为止，NLog 日志记录一直没有问题。

我们遇到的问题是，在正常运行几个小时后(似乎是随机的，无法找到规律)，它会创建几乎重复的日志行。一旦开始，它会继续记录每一行两次或三次。有时它会随机回到一行。

行将在 DatabaseLogFormatter 中读取的耗时上有所不同，这意味着正在重新格式化请求(而不是 NLog 问题)。

public class NLogFormatter : DatabaseLogFormatter
{
    private static readonly DbType[] StringTypes = { DbType.String, DbType.StringFixedLength, DbType.AnsiString, DbType.AnsiStringFixedLength, DbType.Date, DbType.DateTime, DbType.DateTime2, DbType.Time, DbType.Guid, DbType.Xml};

    public NLogFormatter(DbContext context, Action<string> writeAction)
        : base(context, writeAction)
    {
    }

    public override void LogCommand<TResult>(
        DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {

        var builder = new StringBuilder();
        builder.Append($"COMMAND|{(command.CommandType == CommandType.StoredProcedure ? "EXEC " :"")}{command.CommandText.Replace(Environment.NewLine, " ")} ");
        foreach (var parameter in command.Parameters.OfType<DbParameter>())
        {
            builder.Append("@")
                .Append(parameter.ParameterName)
                .Append(" = ")
                .Append(parameter.Value == null || parameter.Value == DBNull.Value ? "null" : StringTypes.Any(t => t == parameter.DbType) ? $"'{parameter.Value}'" : parameter.Value);
            builder.Append(", ");
        }

        Write(builder.ToString());
    }

    public override void LogResult<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
    {
        var sw = Stopwatch;
        Write($"COMPLETED|{command.CommandText.Replace(Environment.NewLine, " ")}|{sw.ElapsedMilliseconds}ms");
    }
    //rest removed for brevity
}

和 EF 上下文(来自 DB 优先模型)。数据库调用是使用未修改的 EF 生成的函数进行的，我们主要使用存储过程。

public class EfDbConfiguration : DbConfiguration
{
    public EfDbConfiguration()
    {
        SetDatabaseLogFormatter((context, action) => new NLogFormatter(context, action));
    }
}

public class EfFunctions
{
    private readonly EfEntities _db = new EfEntities { Database = { Log = Logger.LogEfRequest } };
    //Function calls etc
}

日志输出如何显示的示例

2017-10-22 23:47:22.0611|Debug|REQUEST|Example.Page|POST|/example/page
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.0611|Debug|DB|COMMAND|EXEC [Test].[GetOrder] @OrderNumber = '123456789', @ErrorCode = null, 
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|DB|COMPLETED|[Test].[GetOrder]|149ms
2017-10-22 23:47:22.2111|Debug|APP|No order or session, creating new session|123456789 

Answer 1

Cataklysim 的评论指出了正确的方法。

问题是对请求链所有部分的处理不正确，在 DbContext 对象未被处理的地方存在不匹配，即使在创建新的 DbContext(以及新的记录器)时，现有记录器仍保持事件状态，并且然后两者都会捕获事件并记录。测试时它没有在本地显示，因为服务器需要时间来降低和启动新线程以创建多个 DbContext。

确保 Dispose disposables，手动(并确保 Dispose 整个链)或使用 Using(Disposable) 在其 block 的末尾调用 Dispose。