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

`The NLog logging has worked without issue until now.` - What changed? — Mark C., Sep 28 '17 at 13:28
@MarkC. Bad phrasing on my part; it still works fine beyond the EF logging. — muddymess, Sep 28 '17 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, Oct 24 '17 at 07:46
@AkashKava DB is on different server on same local network, on a dedicated server. Retry policy is set to no-retry, as far as I can tell. It doesn't seem to be actually firing any more requests; I'll run a trace to verify next time it occurs. — muddymess, Oct 24 '17 at 07:57
@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, Oct 24 '17 at 08:16
@AkashKava The HTTP requests are fine as well, they're being processed in a timely manner. The rest of the logging via the same NLog target logs every row correctly, and shows no signs of a request being duplicated. — muddymess, Oct 24 '17 at 08:47
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, Oct 24 '17 at 11:10
@Cataklysim I'll try being more strict with disposal. Do you mean just straight up taking the default EF logging output and seeing what we get? — muddymess, Oct 24 '17 at 13:03
@muddymess Yes. May be that you log right, but EF sends multiple queries. — Cataklysim, Oct 24 '17 at 13:57
Trying to get it to log duplicates on our test and/or stage environments, and it does happen, but never when I'm actively trying. Our logs on production are too critical to allow for testing on it. — muddymess, Oct 24 '17 at 14:53
do you use a DI framework like Autofac or Ninject ? Maybe inject a guid in the lifetimescope, and log that guid in this data. (see article: https://stackoverflow.com/questions/26288494/asp-net-mvc-unique-id-per-request) Then you can known if the database calls come from the same http request or from another http request. If they come from different http requests, you can then check on the client , otherwise you will have to check the server. In the second case, the logging of the current thread id could also get you more insights. — Ben Croughs, Oct 26 '17 at 09:56
Did u check, if the problem occurs if the NLog is replaced by an ordinary TextWriter? — kara, Dec 01 '17 at 12:30
I've also run into retries with HTTP requests similar to what AkashKava described. It appears that automatic retries are the default behavior of the HttpClient's async calls. Making sure that the call is idempotent (only affects the outcome once regardless of how many times it's run) would likely prevent the issue that you're running into. One approach to making that happen would be to include a token with the params to the log. If you get that token more than once, just return. (You'd need a lock around the check. It gets trickier if you have multiple servers.) — Doug Johnson, Jan 23 '18 at 05:49

score 1 · Accepted Answer · answered Mar 15 '18 at 09:55

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.

Entity Framework logs duplicates

1 Answers1