Entity Framework logs duplicates

Question

We're running Entity Framework 6 and have a DatabaseLogFormatter that formats our data, and it's logged via an NLog AsyncTargetWrapper to a file. The application is an MVC5 web app.

The DatabaseLogFormatter is mostly empty stubs, except LogCommand and LogResult. Both of which format the data correctly. The NLog logging has worked without issue until now.

The issue we're running into is that after a few hours uptime (seems random, haven't been able to find a pattern) it will create almost duplicate log rows. Once it starts it continues to log every row twice or thrice. Sometimes it randomly goes back to one row.

The rows will differ in elapsed time which is read in the DatabaseLogFormatter, implying that the requests are being reformatted (and not an NLog issue).

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
}

And EF context (from DB first model). DB calls are made using the unmodified EF generated functions and we mainly use stored procedures.

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
}

Example of how log output can appear

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

Was pointed in the right way by a comment from Cataklysim.

The problem was incorrect disposal of all parts of the request chain, there was a mismatch where the DbContext object was not disposed and that kept the existing logger alive even when a new DbContext was created (and with it a new logger) and then both would catch events and log. It was not showing up locally when testing because the server needed time to spin down and up new threads to create multiple DbContexts.

Make sure to Dispose disposables, either manually (and make sure to Dispose the entire chain) or by making use of Using(Disposable) which calls Dispose at the end of it's block.