Skip to content

Microsoft.Data.SqlClient.SqlException log noise #261

@devodo

Description

@devodo

I am using DistributedLock.SqlServer for distributed locking in an Azure hosted app that is logging to Application Insights. The locking is working great, thank you! However, it is causing a lot of log noise showing up in Application Insights as Sql Server dependency failures due to the following exception occurring fairly often:

Microsoft.Data.SqlClient.SqlException (0x80131904): A severe error occurred on the current command.  The results, if any, should be discarded.
Operation cancelled by user.
   at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, SqlCommand command, Boolean callerHasConnectionLock, Boolean asyncClose)
   at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted)
   at Microsoft.Data.SqlClient.SqlCommand.CompleteAsyncExecuteReader(Boolean isInternal, Boolean forDescribeParameterEncryption)
   at Microsoft.Data.SqlClient.SqlCommand.InternalEndExecuteNonQuery(IAsyncResult asyncResult, Boolean isInternal, String endMethod)
   at Microsoft.Data.SqlClient.SqlCommand.EndExecuteNonQueryInternal(IAsyncResult asyncResult)
   at Microsoft.Data.SqlClient.SqlCommand.EndExecuteNonQueryAsync(IAsyncResult asyncResult)
   at Microsoft.Data.SqlClient.SqlCommand.<>c.<InternalExecuteNonQueryAsync>b__193_1(IAsyncResult asyncResult)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
ClientConnectionId:d7f88130-dbb2-4509-8019-92a4428b47a3

I am using the following code to acquire a lock:

await using var handle = await _lockProvider.AcquireLockAsync(
    lockKey,
    lockingConfig.Value.LockTimeout,
    cancellationToken);

The Microsoft.Data.SqlClient.SqlException is only occurring if handle.HandleLostToken is called.

I was able to observe this locally by registering a custom IObserver<DiagnosticListener>. From this I can see the Microsoft.Data.SqlClient.SqlException is coming from executing the command: WAITFOR DELAY @delay. I can see this command text is defined in the method SqlDatabaseConnection.SleepAsync() that gets called by ConnectionMonitor and the monitor starts when calling handle.HandleLostToken. So I suspect the connection is closing before the command completes resulting in the exception but it gets caught and swallowed by NonThrowingAwaitable<TTask>.

Functionally this does not have an impact but Application Insights telemetry still observes it by default and reports it as a dependency failure. I expect other logging platforms would also be seeing this as their telemetry processing will be capturing .NET exception diagnostics.

I guess this ConnectionMonitor behaviour is all by design and the solution is to add filtering on the telemetry side. So I guess I have arrived at an answer but I'm sharing my findings here anyway in case there is a better solution or it helps others who come across this.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions