title: Entity Framework logs duplicates
body: <p>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.</p>
  
  <p>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.</p>
  
  <p>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.</p>
  
  <p>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).</p>
  
  <pre><code>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&lt;string&gt; writeAction)
          : base(context, writeAction)
      {
      }
  
      public override void LogCommand&lt;TResult&gt;(
          DbCommand command, DbCommandInterceptionContext&lt;TResult&gt; 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&lt;DbParameter&gt;())
          {
              builder.Append("@")
                  .Append(parameter.ParameterName)
                  .Append(" = ")
                  .Append(parameter.Value == null || parameter.Value == DBNull.Value ? "null" : StringTypes.Any(t =&gt; t == parameter.DbType) ? $"'{parameter.Value}'" : parameter.Value);
              builder.Append(", ");
          }
  
          Write(builder.ToString());
      }
  
      public override void LogResult&lt;TResult&gt;(DbCommand command, DbCommandInterceptionContext&lt;TResult&gt; interceptionContext)
      {
          var sw = Stopwatch;
          Write($"COMPLETED|{command.CommandText.Replace(Environment.NewLine, " ")}|{sw.ElapsedMilliseconds}ms");
      }
      //rest removed for brevity
  }
  </code></pre>
  
  <p>And EF context (from DB first model). DB calls are made using the unmodified EF generated functions and we mainly use stored procedures.</p>
  
  <pre><code>public class EfDbConfiguration : DbConfiguration
  {
      public EfDbConfiguration()
      {
          SetDatabaseLogFormatter((context, action) =&gt; new NLogFormatter(context, action));
      }
  }
  
  public class EfFunctions
  {
      private readonly EfEntities _db = new EfEntities { Database = { Log = Logger.LogEfRequest } };
      //Function calls etc
  }
  </code></pre>
  
  <p>Example of how log output can appear</p>
  
  <pre><code>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 
  </code></pre>