Skip to content

SqlConnection.InfoMessage handler does not receive all info messages when SqlCommand.ExecuteReader is used to execute a query #3541

@ronbos

Description

@ronbos

Describe the bug

A clear and concise description of what the bug is.
If SqlCommand.ExecuteReader is used to execute a query that returns rows, and SqlConnection.InfoMessage handler is set, e.g.

                connection.InfoMessage += (s, e) =>
                {
                    Console.WriteLine($"INFO: {e.Message}");
                };

Handler does not receive all debug messages. An example is if a SELECT query is called after set statistics time on is set. A statistics message for execution time is expected in this case, e.g.

SQL Server Execution Times:
   CPU time = 78 ms,  elapsed time = 105 ms.

However, it is not received.

This debug message is received in InfoMessage handler if SqlCommand.ExecuteNonQuery() is used instead.

To reproduce

Invoke following function with an appropriate connectionString and a queryText statement, e.g. "select top 10 * from table_name". This test is trivial as it ignores row results, but in actual use ExecuteReader() would be used to receive rows.

static void test(string connectionString, string queryText, bool useReader)
{
    using (SqlConnection connection = new SqlConnection(connectionString))
    {
        connection.InfoMessage += (s, e) =>
        {
            Console.WriteLine($"INFO: {e.Message}");
        };
        connection.Open();
        using (SqlCommand command = new SqlCommand("set statistics time on", connection))
        {
            command.ExecuteNonQuery();
        }
        if (useReader)
        {
            using (SqlCommand command = new SqlCommand(queryText, connection))
            {
                using (SqlDataReader reader = command.ExecuteReader())
                {
                    while (reader.Read())
                    {
                        //ignore in this strawman test
                    }
                }
            }
        }
        else
        {
            using (SqlCommand command = new SqlCommand(queryText, connection))
            {
                command.ExecuteNonQuery();
            }
        }
        using (SqlCommand command = new SqlCommand("set statistics time off", connection))
        {
            command.ExecuteNonQuery();
        }
    }
}

NOTE: I have also tested with iterator for e.Errors in InfoMessage handler, same behavior:

connection.InfoMessage += (s, e) =>
{
    foreach (SqlError error in e.Errors)
    {
        Console.WriteLine($"INFO: {error.Message}");
    }
};

Expected behavior

Expected output is

INFO: SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 3 ms.

 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.
INFO: SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 0 ms.

This is received when useReader == false. If useReader == true, we instead do not receive SQL Server Execution Times. QueryText execution generates two messages, SQL Server parse and compile time and SQL Server Execution Times, but only first one is reported.

INFO: SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 5 ms.
INFO: SQL Server parse and compile time:
   CPU time = 0 ms, elapsed time = 0 ms.

Further technical details

Microsoft.Data.SqlClient version: tested with 5.2.1, 6.0.2, 6.1.0
.NET target: .NET Framework 4.7.2
SQL Server version: SQL Server 2022
Operating system: Windows 11, Windows Server 2022

Additional context
Add any other context about the problem here.

Metadata

Metadata

Assignees

No one assigned

    Labels

    Area\DocumentationUse this for issues that requires changes in public documentations/samples.Triage Done ✔️Issues that are triaged by dev team and are in investigation.

    Type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions