Database.Log not logging appended SQL from interceptor in Entity Framework

Question

I am appending this code below successfully to the SQL Query being created from Entity Framework with an interceptor inside a Scope, but the Database.Log below, called afterwards, doesnt show the OPTION(RECOMPILE) in the query so I am not sure its even being executed.

Calling Code

  using (new OptionRecompileScope(_divisionPoolsRepository.DataContext))
            {
                divisionTeamResultsIds.AddRange(_divisionPoolsRepository.DataContext.DivisionBracketParticipants.Where(g => g.DivisionBracketParticipantPool.DivisionPoolId == divisionPoolId.Value).Select(g => g.DivisionGameTeamResultId).Distinct().ToList());
            }

OptionRecompileScope.cs

private void AddOptionRecompile(IDbCommand command)
            {
                command.CommandText += " OPTION(RECOMPILE)";
            }

The code above is from this link EF 6 Parameter Sniffing

DataContext.cs

public class DataContext : DbContext
    {
        private readonly ILogger _logger;

        public DataContext(ILogger logger)
        {
            Database.SetInitializer<DataContext>(null);

            Configuration.LazyLoadingEnabled = false;
            Configuration.ProxyCreationEnabled = false;

            _logger = logger;

            if (Config.Debugging.LogDatabase)
            {
                Database.Log = q => _logger.Debug(q);
            }
        }
}

Entire Scope Class

public class OptionRecompileScope : IDisposable
    {
        private const string QueryHintText = " OPTION(RECOMPILE)";
        private readonly OptionRecompileDbCommandInterceptor interceptor;

        public OptionRecompileScope(DbContext context)
        {
            interceptor = new OptionRecompileDbCommandInterceptor(context);
            DbInterception.Add(interceptor);
        }

        public void Dispose()
        {
            DbInterception.Remove(interceptor);
        }

        private class OptionRecompileDbCommandInterceptor : IDbCommandInterceptor
        {
            private readonly DbContext dbContext;

            internal OptionRecompileDbCommandInterceptor(DbContext dbContext)
            {
                this.dbContext = dbContext;
            }

            public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
            {
            }

            public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
            {
            }

            public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
            {
                if (ShouldIntercept(command, interceptionContext))
                {
                    AddOptionRecompile(command);
                }
            }

            public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
            {
            }

            public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
            {
                if (ShouldIntercept(command, interceptionContext))
                {
                    AddOptionRecompile(command);
                }
            }

            public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
            {
            }

            private void AddOptionRecompile(IDbCommand command)
            {
                if (!command.CommandText.EndsWith(QueryHintText))
                {
                    command.CommandText += QueryHintText;
                }
            }

            private bool ShouldIntercept(IDbCommand command, DbCommandInterceptionContext interceptionContext)
            {
                return
                    command.CommandType == CommandType.Text &&
                    command is SqlCommand &&
                    interceptionContext.DbContexts.Any(interceptionDbContext => ReferenceEquals(interceptionDbContext, dbContext));
            }
        }
    }

Do you register the interceptor by `DbInterception.Add(...)`? — Gert Arnold, Aug 07 '21 at 18:54
Yes, the code has it, and I said the code listed gets hit. The scope adds it. — Mike Flynn, Aug 07 '21 at 18:54
OK, just to be sure. A quick test here points out that it's a question of sequence. If the `Log` is subscribed *after* adding the interceptor it will log the modified command, otherwise it logs the original command. No doubt this has to do with the logger itself also being an interceptor and they operate as a pipeline. — Gert Arnold, Aug 07 '21 at 19:12
You could go for a solution like [this](https://stackoverflow.com/a/64387065/861716). I.e. just register the interceptor once at startup and switch its effect on or off. — Gert Arnold, Aug 07 '21 at 19:19
But isn’t the logger added before the other in the datacontext constructor and db is password to the scope with the other interceptor? Why does that even matter with the logging is a lambda and doesn’t get executed unless a query is called. — Mike Flynn, Aug 07 '21 at 19:20
I don't know exactly what happens when `Log` is set (I'd have to check the source code, but it probably registers the logging interceptor at that moment), I just notice that the order of events matters. Your code first sets `Log` and then (re)registers the interceptor, so `Log` gets the unmodified command. — Gert Arnold, Aug 07 '21 at 19:32
Well I tried something and it worked in the answer I posted. Thanks for the help. — Mike Flynn, Aug 07 '21 at 21:18

score 2 · Accepted Answer · answered Aug 07 '21 at 21:18

It looks like the order was the issue. I just readded it inside the OptionRecompileScope constructor and the output is correct now.

public OptionRecompileScope(DbContext context, ILogger logger)
        {
            interceptor = new OptionRecompileDbCommandInterceptor(context);
            DbInterception.Add(interceptor);
            if (Config.Debugging.LogDatabase)
            {
                context.Database.Log = q => logger.Debug(q);
            }
        }

Database.Log not logging appended SQL from interceptor in Entity Framework

1 Answers1