12

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 
13
  • The NLog logging has worked without issue until now. - What changed?
    – Mark C.
    Commented Sep 28, 2017 at 13:28
  • @MarkC. Bad phrasing on my part; it still works fine beyond the EF logging.
    – muddymess
    Commented Sep 28, 2017 at 14:11
  • @muddymess EF has introduced Retry mechanism in which if transaction is timed out, it will retry, you should check what are the defaults for retry settings. Is Database on same server or remote server? Is it on shared or dedicated server?
    – Akash Kava
    Commented Oct 24, 2017 at 7:46
  • 2
    @muddymess If you notice, Chrome browser etc will refire the HTTP request if it timed out, So if server is highly occupied, and if it didn't send first byte, after a timeout browser will retry. This also could generate same EF log as everything would be same, if you scan through HTTP logs, you might get more help.
    – Akash Kava
    Commented Oct 24, 2017 at 8:16
  • 1
    Maybe try to dispose unused objects if possible or even use using. Have you tried log the transactions the EF sets? An example for that: this.DbContext.Database.Log = l => builder.Append(l);
    – Cataklysim
    Commented Oct 24, 2017 at 11:10

1 Answer 1

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 its block.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.