Moved from: bobsql.com
I was recently contacted by Christophe Laporte posing a very interesting question.
"This is about the blog post you published a while ago, but I’ have questions regarding the error which is firing an XEvent almost every 10 ms.
I’ve done a bunch of simple testing on a lab environment to reproduce the issue of my customer and it appears that the event is raised on the logout statement, but not on the login statement.
Repro (Powershell commands and XEvent):
$connectionString = 'Data Source=ServerName;database=master;Pooling=False;Trusted_Connection=yes'
$sqlConnection = New-Object System.Data.SqlClient.SqlConnection $connectionString
$sqlConnection.Open()
Start-Sleep -s 1
$sqlConnection.Close()
CREATE EVENT SESSION [LoginIssues] ON SERVER
ADD EVENT sqlserver.connectivity_ring_buffer_recorded(
ACTION(sqlos.task_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.is_system,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text,sqlserver.username)),
ADD EVENT sqlserver.login(SET collect_options_text=(1)
ACTION(sqlos.task_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.is_system,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text,sqlserver.username)),
ADD EVENT sqlserver.logout(
ACTION(sqlos.task_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.is_system,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text,sqlserver.username)),
ADD EVENT sqlserver.security_error_ring_buffer_recorded(
ACTION(sqlos.task_time,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.client_pid,sqlserver.database_id,sqlserver.database_name,sqlserver.is_system,sqlserver.nt_username,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text,sqlserver.username))
ADD TARGET package0.ring_buffer
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO
Using Pooling=false forces the logout, else the event connectivity_ring_buffer_recorded with error 17830 is not raised.
The XEvent records the login event, and only when logout is sent by the client application, 1 second later, the event connectivity_ring_buffer_recorded event is fired. And then the logout.
I started debugging the scenario and found that if I replaced the sleep command with any SQL command execution the behavior no longer reproduced.
$cmd = $sqlConnection.CreateCommand()
$cmd.CommandText = "select 100";
$cmd.ExecuteScalar()
$cmd.Dispose()
I then reproduced the same problem in a C# (.Net) application as well as an ODBC application. In the process of reproducing the behavior I stepped through the client side (SNI) code and found no difference in how the connection is being established or closed, with or without the command execution.
Looking at network traces, with my colleague Kapil, we found the network trace was identical for the connect and disconnect events, with or without the command execution.
This led me to start looking closer at the SQL Server SNI code where I uncovered the reason for the 17830 logging and filed a work item with the connectivity team to review the behavior.
This issue stems from the success or failure of the first TDS packet read after the login is complete.
The disconnect of the client results in a close of the socket. The client socket close then results in a read completion on the SQL Server indicating the connection no longer exists and SQL Server should proceed with disconnect activities.
The SQL Server disconnect code path always logs a connectivity ring buffer entry for the close. In this case there is an additional check. If the client logged in and never sent a request the 17830 is logged indicating the first packet after login was never received. Therefore the 17830 is recorded at the point of disconnect.
This pattern indicates you have a client connecting to the SQL Server, never running a SQL command, and disconnecting. It is most likely an application or networking/firewall error, but you should review the information carefully to ensure it is not an unexpected probe of the server.
Thanks to Christophe Laporte for an interesting question.
- Bob Dorr
Updated Feb 06, 2022
Version 1.0BobDorr
Microsoft
Joined January 13, 2022
SQL Server Blog
Follow this blog board to get notified when there's new activity