实体框架记录重复项

Question

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

DatabaseLogFormatter 大部分是空存根，除了 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 第一个模型）。 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 的Using(Disposable)。