The SQL logged by EF doesn't reflect changes made by interceptors

[ken-swyfft]

Bug description

In EF 9 and previous versions, the SQL which EF logged reflected changes to that SQL made by user-registered interceptors. In EF 10, that's no longer the case, which makes it difficult to debug certain classes of problems. I've attached a runnable Program.cs that reproduces the problem.

In EF 9.0.11, you'll see that the OPTION (RECOMPILE) is included in the logged SQL; in EF 10 it's not, even though it is sent to the DB.

Your code

using Microsoft.EntityFrameworkCore;
using Microsoft.EntityFrameworkCore.Diagnostics;
using System.Data.Common;

namespace EFCoreLoggingBugRepro;

/// <summary>
/// This repro demonstrates that in EF Core 10, DbCommandInterceptor modifications to CommandText
/// are NOT reflected in EF Core's logging output, even though the modifications ARE sent to the database.
///
/// Expected behavior: The logged SQL should include "OPTION (RECOMPILE)" appended by the interceptor.
/// Actual behavior: The logged SQL shows the original SQL without the interceptor's modification.
///
/// The interceptor IS working - if you run SQL Server Profiler, you'll see "OPTION (RECOMPILE)" in the
/// actual query sent to the database. But EF Core's logging captures the CommandText BEFORE the
/// interceptor modifies it.
/// </summary>
class Program
{
    private const string UseOptionRecompileTag = "-- Use option recompile";

    static async Task Main(string[] args)
    {
        // Use your local SQL Server connection string
        var connectionString = "Server=localhost;Database=master;Integrated Security=true;TrustServerCertificate=true;";

        var loggedSqlStatements = new List<string>();

        var options = new DbContextOptionsBuilder<TestDbContext>()
            .UseSqlServer(connectionString)
            .LogTo(sql =>
            {
                loggedSqlStatements.Add(sql);
                Console.WriteLine($"[EF LOG] {sql}");
            }, Microsoft.Extensions.Logging.LogLevel.Information)
            .AddInterceptors(new OptionRecompileInterceptor())
            .Options;

        await using var context = new TestDbContext(options);

        Console.WriteLine("=== Executing query with WithRecompile tag ===\n");

        // Build a query tagged with our recompile hint
        var query = context.Database
            .SqlQueryRaw<int>($"{UseOptionRecompileTag}\nSELECT 1 AS Value");

        // Check ToQueryString() BEFORE execution
        var toQueryStringResult = query.ToQueryString();
        Console.WriteLine($"[ToQueryString BEFORE execution]:\n{toQueryStringResult}\n");

        // Execute the query (this triggers the interceptor)
        var result = await query.ToListAsync();

        // Check ToQueryString() AFTER execution (should be the same, interceptor doesn't affect it)
        var toQueryStringAfter = query.ToQueryString();
        Console.WriteLine($"[ToQueryString AFTER execution]:\n{toQueryStringAfter}\n");

        Console.WriteLine("=== Analysis ===\n");

        // Check if the logged SQL contains the OPTION (RECOMPILE) that the interceptor should have added
        var executedCommandLog = loggedSqlStatements
            .FirstOrDefault(s => s.Contains("Executed DbCommand") && s.Contains("SELECT 1"));

        if (executedCommandLog != null)
        {
            Console.WriteLine("Found executed command log entry.");

            if (executedCommandLog.Contains("OPTION (RECOMPILE)"))
            {
                Console.WriteLine("SUCCESS: OPTION (RECOMPILE) appears in logged SQL.");
            }
            else
            {
                Console.WriteLine("BUG: OPTION (RECOMPILE) does NOT appear in logged SQL!");
                Console.WriteLine("     The interceptor modified CommandText, but EF Core logged the ORIGINAL SQL.");
                Console.WriteLine("     Run SQL Server Profiler to verify the modification IS being sent to the database.");
            }

            if (executedCommandLog.Contains(UseOptionRecompileTag))
            {
                Console.WriteLine("     (The tag comment IS present in the log, proving the query was tagged)");
            }
        }
        else
        {
            Console.WriteLine("Could not find executed command log entry.");
        }

        // Analyze ToQueryString() behavior
        Console.WriteLine("\n--- ToQueryString() Analysis ---");
        if (toQueryStringResult.Contains("OPTION (RECOMPILE)"))
        {
            Console.WriteLine("ToQueryString(): Contains OPTION (RECOMPILE)");
        }
        else
        {
            Console.WriteLine("ToQueryString(): Does NOT contain OPTION (RECOMPILE)");
            Console.WriteLine("     (Expected - ToQueryString() generates SQL from LINQ expression tree,");
            Console.WriteLine("      which is before any DbCommandInterceptor modifications)");
        }
    }
}

/// <summary>
/// Interceptor that appends OPTION (RECOMPILE) to queries tagged with "-- Use option recompile"
/// </summary>
public class OptionRecompileInterceptor : DbCommandInterceptor
{
    private const string UseOptionRecompileTag = "-- Use option recompile";

    public override InterceptionResult<DbDataReader> ReaderExecuting(
        DbCommand command,
        CommandEventData eventData,
        InterceptionResult<DbDataReader> result)
    {
        ManipulateCommand(command);
        return base.ReaderExecuting(command, eventData, result);
    }

    public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(
        DbCommand command,
        CommandEventData eventData,
        InterceptionResult<DbDataReader> result,
        CancellationToken cancellationToken = default)
    {
        ManipulateCommand(command);
        return base.ReaderExecutingAsync(command, eventData, result, cancellationToken);
    }

    private static void ManipulateCommand(DbCommand command)
    {
        if (command.CommandText.Contains(UseOptionRecompileTag, StringComparison.OrdinalIgnoreCase))
        {
            var originalText = command.CommandText;
            command.CommandText = $"{originalText}\nOPTION (RECOMPILE)";

            Console.WriteLine($"[INTERCEPTOR] Modified CommandText:");
            Console.WriteLine($"[INTERCEPTOR]   Before: {originalText}");
            Console.WriteLine($"[INTERCEPTOR]   After:  {command.CommandText}");
        }
    }
}

public class TestDbContext(DbContextOptions<TestDbContext> options) : DbContext(options);

Stack traces

Verbose output

=== Executing query with WithRecompile tag ===

[ToQueryString BEFORE execution]:
-- Use option recompile
SELECT 1 AS Value


[INTERCEPTOR] Modified CommandText:
[INTERCEPTOR]   Before: -- Use option recompile
SELECT 1 AS Value

[INTERCEPTOR]   After:  -- Use option recompile
SELECT 1 AS Value

OPTION (RECOMPILE)
[EF LOG] info: 11/24/2025 16:31:38.968 RelationalEventId.CommandExecuted[20101] (Microsoft.EntityFrameworkCore.Database.Command) 
      Executed DbCommand (31ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      -- Use option recompile
      SELECT 1 AS Value
[ToQueryString AFTER execution]:
-- Use option recompile
SELECT 1 AS Value


=== Analysis ===

Found executed command log entry.
BUG: OPTION (RECOMPILE) does NOT appear in logged SQL!
     The interceptor modified CommandText, but EF Core logged the ORIGINAL SQL.
     Run SQL Server Profiler to verify the modification IS being sent to the database.
     (The tag comment IS present in the log, proving the query was tagged)

--- ToQueryString() Analysis ---
ToQueryString(): Does NOT contain OPTION (RECOMPILE)
     (Expected - ToQueryString() generates SQL from LINQ expression tree,
      which is before any DbCommandInterceptor modifications)

EF Core version

10.0.0

Database provider

Microsoft.EntityFrameworkCore.SqlServer

Target framework

.NET 10

Operating system

Windows 11

IDE

No response

[roji]

Confirmed regression in 10.0. This could be because of the logging changes we did to redact inlined constants (#35757, /cc @cincuranet).

Minimal repro

await using var context = new BlogContext();
await context.Database.EnsureDeletedAsync();
await context.Database.EnsureCreatedAsync();

_ = await context.Blogs.ToListAsync();

public class BlogContext : DbContext
{
    public DbSet<Blog> Blogs { get; set; }

    protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        => optionsBuilder
            .UseSqlServer(Environment.GetEnvironmentVariable("Test__SqlServer__DefaultConnection"))
            .AddInterceptors(new OptionRecompileInterceptor())
            .LogTo(Console.WriteLine, LogLevel.Information)
            .EnableSensitiveDataLogging();

    public class OptionRecompileInterceptor : DbCommandInterceptor
    {
        public override ValueTask<InterceptionResult<DbDataReader>> ReaderExecutingAsync(
            DbCommand command,
            CommandEventData eventData,
            InterceptionResult<DbDataReader> result,
            CancellationToken cancellationToken = default)
        {
            command.CommandText += "\nOPTION (RECOMPILE)";
            return base.ReaderExecutingAsync(command, eventData, result, cancellationToken);
        }
    }
}

public class Blog
{
    public int Id { get; set; }
    public string Name { get; set; }
}

[roji]

Here's what's happening:

• EF must sometimes inlined query parameters into the SQL; since parameters may contain sensitive data, we did #35757 in EF 10, which makes EF redact inlined constants from the logged SQL by default.
• This means that we now have two SQLs: the logged one (where inlined constants are redacted), and the executed one, which is found on DbCommand.CommandText.
• Command interceptors only modify commands, so the logged SQL doesn't get "intercepted" - this is the source of the behavior change tracked by this issue.

Possible next steps:

• We could relatively easily fix this for when there's no redacting (logged SQL = executed SQL). However, it's a bit problematic for the logged SQL to generally reflect interceptors, but the moment you change the query in a way that requires redacting, suddenly your interception changes disappear (unexpected/inconsistent).
• We could make the interceptor changes visible when EnableSensitiveLogging() is set (here also logged SQL = executed SQL). But I believe we should absolutely not do that - people should absolutely not be doing EnableSensitiveLogging() in order to see interceptor changes, as this would potentially leak actual sensitive data (EnableSensitiveLogging() should generally be more of a testing/development thing).
• We could introduce a new kind of interceptor, specifically for SQL changes; instead of modifying the command, it would accept SQL and return the modified SQL. We'd run this interceptor twice, once for the logged and once for the executed SQL. But this is a bit heavy, adding yet another interceptor to the mix.

Let's think further and discuss what to do.

[stevendarby]

FWIW the original issue https://github.com/dotnet/efcore/issues/24539 had some thoughts on implementation which might not have been seen when implementing it against the newer issue - I've no idea if they help at all though.

[roji]

@stevendarby anything in particular from there? I'm not seeing anything helpful.

[pinkfloydx33]

We use an interceptor in conjunction with RLS in Postgres. We set a local session variable by prepending the proper statement into all command text.

The way it's logged right now is useful when tracking down issues as it adds some context to the command we might not otherwise have. Conversely, it's only useful when debugging a problem and it'd be kind of neat if we had a way to drop it otherwise. Removing it would also ensure that two otherwise identical queries are logged as such.

Just noting that while we've not upgraded yet, I probably would've reported this in the next few weeks myself. It's certainly not the end of the world but it would be nice if there was some way to gain consistency with prior versions. I figured I'd provide some additional context in case it helps here.