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