Add interception event to be fired when EF has finished consuming a result set

[windhandel]

File a bug

It was suggested on an issue that a new issue be created for the issue I am experiencing. Here is the behavior.

I have attempted to build both an IDbConnectionInterceptor or IDbCommandInterceptor implementation that allows me to attach to the underlying SqlConnection's InfoMessage event in order to retrieve the messages created by running the command:

SET STATISTICS IO ON;

just prior to individual EF Core SQL command.

Initially, I attempted to do this within an IDbCommandInterceptor since I must modify the command text to include the prefixed statement. Although the IDbCommandInterceptor fired, no such event could be picked up, despite attaching to the event.

At @roji 's suggestion, I attempted to create an implementation of IDbConnectionInterceptor, but none of the events on the basic implementation are being fired.

Include your code

IDbConnectionInterceptor:

    public class BareDbConnectionInterceptor : DbConnectionInterceptor, IDbConnectionInterceptor
    {
        bool attached = false;

        public BareDbConnectionInterceptor()
        {
        }

        void InfoMessageHandler(object sender, SqlInfoMessageEventArgs args)
        {
            Debug.WriteLine(args.Message);
        }

        void attachStatisticsTracking(SqlConnection sqlConnection)
        {
            if (attached)
            {
                sqlConnection.InfoMessage += InfoMessageHandler;
                attached = true;
            }
        }

        public override InterceptionResult ConnectionOpening(DbConnection connection, ConnectionEventData eventData, InterceptionResult result)
        {
            attachStatisticsTracking(connection as SqlConnection);
            return result;
        }

        public override Task<InterceptionResult> ConnectionOpeningAsync(DbConnection connection, ConnectionEventData eventData, InterceptionResult result, CancellationToken cancellationToken = default)
        {
            attachStatisticsTracking(connection as SqlConnection);
            return Task.FromResult(result);
        }

        public override void ConnectionOpened(DbConnection connection, ConnectionEndEventData eventData)
        {
            attachStatisticsTracking(connection as SqlConnection);
        }

        public override Task ConnectionOpenedAsync(DbConnection connection, ConnectionEndEventData eventData, CancellationToken cancellationToken = default)
        {
            attachStatisticsTracking(connection as SqlConnection);
            return Task.CompletedTask;
        }

        public override void ConnectionFailed(DbConnection connection, ConnectionErrorEventData eventData)
        {
            base.ConnectionFailed(connection, eventData);
        }
        public override Task ConnectionFailedAsync(DbConnection connection, ConnectionErrorEventData eventData, CancellationToken cancellationToken = default)
        {
            return base.ConnectionFailedAsync(connection, eventData, cancellationToken);
        }

        public override InterceptionResult ConnectionClosing(DbConnection connection, ConnectionEventData eventData, InterceptionResult result)
        {
            return base.ConnectionClosing(connection, eventData, result);
        }

        public override Task<InterceptionResult> ConnectionClosingAsync(DbConnection connection, ConnectionEventData eventData, InterceptionResult result)
        {
            return base.ConnectionClosingAsync(connection, eventData, result);
        }

        public override void ConnectionClosed(DbConnection connection, ConnectionEndEventData eventData)
        {
            base.ConnectionClosed(connection, eventData);
        }

        public override Task ConnectionClosedAsync(DbConnection connection, ConnectionEndEventData eventData)
        {
            return base.ConnectionClosedAsync(connection, eventData);
        }
    }

Adding Interceptors to the DbContext:

        protected override void OnConfiguring(DbContextOptionsBuilder optionsBuilder)
        {
            if (!(_sharedConnectionFactory?.IsNull).GetValueOrDefault(true))
            {
                // Shared connections/transactions enable us to handle the entire test run under a single transaction within the database.
                optionsBuilder
                    .UseSqlServer(_sharedConnectionFactory.Connection)
                    .AddInterceptors(_interceptors);
            }

            base.OnConfiguring(optionsBuilder);
        }

NOTE: A SharedConnectionFactory is being utilized in order to facilitate handling transactions between context instances as part of the same ASP.NET request.

I can confirm the following with breakpoints and stepping over the respective lines of code:

1.) The constructor of the BareDbConnectionInterceptor is being executed.
2.) The IEnumerable (_interceptors, above) contains the BareDbConnectionInterceptor.
3.) That the .AddInterceptors method is being called with the IEnumerable.

However, none of the following methods of the BareDbConnectionInterceptor are being hit by breakpoint and breakpoints are attached correctly:

• ConnectionOpening
• ConnectionOpeningAsync
• ConnectionOpened
• ConnectionOpenedAsync
• ConnectionClosing
• ConnectionClosingAsync
• ConnectionClosed
• ConnectionClosedAsync
• ConnectionFailed
• ConnectionFailedAsync

Include stack traces

No exceptions, including any first-chance exceptions, are being thrown.

Include verbose output

I included what I believed to be the pertinent section, but removed customer-code-specific information

Using assembly '[Project].API'.
Using startup assembly '[Project].API'.
Using application base '[path]\[Project].API\bin\Debug\netcoreapp3.1'.
Using working directory '[path]\[Project].API'.
Using root namespace '[Project].API'.
Using project directory '[path]\[Project].API\'.
Remaining arguments: .
Finding DbContext classes...
Finding IDesignTimeDbContextFactory implementations...
Finding application service provider...
Finding Microsoft.Extensions.Hosting service provider...
Using environment 'Development'.
Using application service provider from Microsoft.Extensions.Hosting.
Found DbContext '[Project]Context'.
Finding DbContext classes in the project...

Include provider and version information

EF Core version:
Database provider: Microsoft.EntityFrameworkCore.SqlServer
Target framework: 3.1.402 [C:\Program Files\dotnet\sdk]
Operating system: Windows 10 V1909
IDE: VS 2019 Version 16.7.3

Thanks for your assistance with this two-part issue.

[ajcvickers]

@windhandel These methods will only be called if EF opens/closes the connection for you. Is this happening, or are you opening the connection at the application level? Debug level logging should fire whenever EF opens and closes the connection--can you check for that?

[windhandel]

Ah, I see, @ajcvickers. My shared connection factory is currently handling the open/close of the connection in order to begin the transaction and carry that transaction through (as there's no easy way to get access to the currently opened transaction off of connection established on your behalf) to other future-connections.

Is there any reason why I shouldn't expect an InfoMessage event to be received back on my SqlConnection within this IDbCommandInterceptor?

    public class BareTrackingCommandInterceptor : DbCommandInterceptor, IDbCommandInterceptor
    {
        bool attached = false;

        public BareTrackingCommandInterceptor()
        {
        }

        void InfoMessageHandler(object sender, SqlInfoMessageEventArgs args)
        {
            Debug.WriteLine(args.Message);
        }

        void attachStatisticsTracking(SqlConnection sqlConnection)
        {
            if (!attached)
            {
                sqlConnection.InfoMessage += InfoMessageHandler;
                attached = true;
            }
        }

        void enableLogicalReads(SqlCommand command)
        {
            command.CommandText = "SET STATISTICS IO ON;" + command.CommandText;
        }

        public override DbCommand CommandCreated(CommandEndEventData eventData, DbCommand result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return base.CommandCreated(eventData, result);
        }

        public override InterceptionResult<DbDataReader> ReaderExecuting(DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return result;
        }

        public override InterceptionResult<object> ScalarExecuting(DbCommand command, CommandEventData eventData, InterceptionResult<object> result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return result;
        }

        public override InterceptionResult<int> NonQueryExecuting(DbCommand command, CommandEventData eventData, InterceptionResult<int> result)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return result;
        }

        public override Task<InterceptionResult<DbDataReader>> ReaderExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult<DbDataReader> result, CancellationToken cancellationToken = default)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return Task.FromResult(result);
        }

        public override Task<InterceptionResult<object>> ScalarExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult<object> result, CancellationToken cancellationToken = default)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return Task.FromResult(result);
        }

        public override Task<InterceptionResult<int>> NonQueryExecutingAsync(DbCommand command, CommandEventData eventData, InterceptionResult<int> result, CancellationToken cancellationToken = default)
        {
            enableLogicalReads(eventData.Command as SqlCommand);
            attachStatisticsTracking(eventData.Connection as SqlConnection);
            return Task.FromResult(result);
        }
    }

Should my shared connection factory be disposing and recreating the SqlConnection with the shared transaction for every connection? Maybe reusing the SqlConnection object has something to do with why the InfoMessage event may not be firing?

[ajcvickers]

@windhandel I don't know anything about the InfoMessage event; you'll probably want to follow up with the SqlClient team on that.

[windhandel]

Hmmmmm, @ajcvickers , I've dumbied up a simple prototype of the SqlConnection and confirmed the functionality works without EF Core. The reason I ask here is because it only seems not to work while using EF Core.

EDIT: It turns out it may not work as expected, see message below.

[windhandel]

Hi @ajcvickers,

Upon further investigation, I suspect I may know the cause of why EF Core may not be causing the InfoMessage event to fire based on this SO article.

Here is an example that may depict the source of the issue. If you set callNextResultAsync to true, then the loop at the bottom is called, which is required in order to get to the second result which contains the info messages.

If this is not being called by EF (even though a second result is not expected), the SQL Connection's InfoMessage event will not be fired.

Are you aware of whether NextResultAsync is being called, despite no additional results being expected by EF Core?

class Program
    {
        static async System.Threading.Tasks.Task Main(string[] args)
        {
            bool callNextResultAsync = false;

            SqlConnection connection = new SqlConnection("connectionstring");
            connection.Open();
            var trans = connection.BeginTransaction();

            connection.InfoMessage += Connection_InfoMessage;
            
            SqlCommand cmd = new SqlCommand();
            cmd.Connection = connection;
            cmd.Transaction = trans;

            cmd.CommandText = "SET STATISTICS IO ON;SELECT * FROM sys.objects";
            using (var reader = await cmd.ExecuteReaderAsync())
            {
                var incr = 0;
                while (await reader.ReadAsync())
                {
                    //Statements to read data from Table1
                    Console.WriteLine(reader.GetString(0));
                    incr++;
                }

                while (callNextResultAsync && await reader.NextResultAsync())
                {
                    while (await reader.ReadAsync())
                    {
                        //Statements to read data from Table2
                        Console.WriteLine(reader.GetString(0));
                        incr++;
                    }
                }
            }
        }

        private static void Connection_InfoMessage(object sender, SqlInfoMessageEventArgs e)
        {
            Console.WriteLine(e.Message);
        }
    }

Thanks,
Jeff

[windhandel]

I've confirmed the fix to EF Core by making the additional call to NextResult which isn't being done.

I added this line into my IDbCommandInterceptor and now the InfoMessage event is being called correctly:

        public override Task<DbDataReader> ReaderExecutedAsync(DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default)
        {
            result.NextResult();

            return base.ReaderExecutedAsync(command, eventData, result, cancellationToken);
        }

[smitpatel]

Can you describe why does EF Core need to call NextResult? It certainly does not seem to cause any error in results/data read from server.

[windhandel]

Sure, @smitpatel , if you take a quick look at my SQL Server-agnostic example, above, and change the callNextResultAsync to true/false for different executions, it will become apparent.

False - SqlConnection's InfoMessage event is not fired
True - SqlConnection's InfoMessage event is fired

The call to NextResult does not determine result success or failure, but without calling NextResult, the expected side effect of firing the underlying connections InfoMessage event will not happen.

Note:

 connection.InfoMessage += Connection_InfoMessage;

[smitpatel]

So you are actually editing the SqlCommand we send and add statistics query in front of it. Yes, EF Core want call NextResult since we only sent one command to server. Interceptor decided to add another command in front of it. The interceptor should intercept the DbDataReader after it is opened, read the statistics data generated by first query, advance reader to NextResult before returning to EF Core. As you have shown here #23535 (comment)

There is nothing actionable on EF Core side. We are doing exact processing for the command we generated. Interceptor do whatever is required to process if they change the command text.

[windhandel]

You only offered one-such example that passes your statement, there are a few that do not pass your statement as true.

• A stored procedure that has informational messages
• A sql connection that previously fires any number of message outputting session-level statements, including:

SET STATISTICS IO ON;
SET STATISTICS TIME ON;

As it stands, if EF Core does not call NextResult, then the InfoMessage event will not be fired, which is not expected behavior.

[windhandel]

@ajcvickers, @roji, @AndriySvyryd - you were surprised by my prior response on #11564. The above response to an obvious bug in EF Core is the sort of thing that ends in the type of frustration I expressed previously.

[smitpatel]

Can please explain why EF Core need to call "NextResult" when EF Core does not send multiple commands in a batch?