dotnet / dotnet/SqlClient

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

Open
#3,541 2 comments 0 reactions 0 assignees View on GitHub
Area\Documentation
Dominant language
C#
Stars
989
Forks
340
Avg merge
4d 19h
Merged PRs (30d)
72

Description

### 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](https://learn.microsoft.com/en-us/sql/t-sql/statements/set-statistics-time-transact-sql?view=sql-server-ver17) 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.
```c#
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:**
```c#
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.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.