16,000 SqlExceptions logged in two minutes from one user

98 views Asked by At

I created an exception logging system by having a handler for System.Windows.Forms.Application.ThreadException. I am fairly confident in the soundness of my logging, but this is making me wonder what could be causing this. And furthermore, how so many Exceptions could be logged onto the server when the server is so slow it's causing timeouts.

Basically, there have been a few instances when our SQL server was doing an import process in the middle of the day and users were getting SqlExceptions with an Exception.Message of "Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding". Now the majority of the exceptions logged during this time were spaced out normally, but on 3 different days, one client logged thousands of this SqlException over the course of a couple minutes.

So I'm asking:

  1. Could the logging code be the culprit for generating so many exceptions logged
  2. If there's anything in System.Data.SqlClient behind the scenes that could generate this much, and if there's any configuration to prevent this.
  3. If there's anything in event handling that could cause events to be resent so many times.

The call of the logging function is a straight line, which leads me to believe that it is actually catching thousands of exceptions, although I can't fathom how that many could be generated.

There is, however, a fallback loop in the logger which I'm wondering if it could be the cause. Although in my testing uncaught exceptions while in an exception handler cause a program crash, so I can't see an exception during exception handling then being handled and logged itself. In addition, none of the 21.5k total stacktraces indicate the exception occurring in the handler.

So here's the code for the logger itself: (note that tries and associated logic is a new addition to prevent potentially endless looping)

    ''' <summary>
    ''' Tries to log an Exception to the database.
    ''' </summary>
    ''' <param name="out">The results of Exception handling</param>
    ''' <param name="ex">The Exception to log.</param>
    ''' <param name="customMessage">A custom message to append to the Exception's message when logging to DB.</param>
    Private Shared Sub LogException(ByVal out As ExceptionLogOutcome, ByVal ex As Exception, Optional ByVal customMessage As String = "", Optional ByVal priority As ExceptionDE.Priority = ExceptionDE.Priority.Medium)
        If ex IsNot Nothing Then

            out.ExceptionDataEntity = New DataEntity.ExceptionDE(ex, priority, CurrentBatchAuditDate, CurrentMachineID, CurrentBatchID, CurrentDocNum, CurrentTransactionID, CurrentUser)

            If customMessage.Length > 0 Then
                out.ExceptionDataEntity.Message &= " NOTE: " & customMessage
            End If

            Dim retry As Boolean = False
            Dim tries As Integer = 0
            Do
                Try
                    DataAccess.LoggerDAO.CreateExceptionLog(out.ExceptionDataEntity)
                Catch exc As SqlClient.SqlException
                    retry = MsgBox(String.Format("An error occured while logging an exception in the program.  Retry?"), MsgBoxStyle.RetryCancel) = MsgBoxResult.Retry

                    If Not retry Then
                        'Failure logging
                        out.WasLogged = False
                        Return
                    End If
                Catch exc As Exception
                    out.LoggingException = exc
                    out.WasLogged = False
                    Return
                End Try
            Loop While retry And tries < 10
        Else
            'Ex is nothing
            out.WasLogged = False
            Return
        End If

        out.WasLogged = True
        Return
    End Sub

What further causes me to rule out my own code as being the problem, though, is that I did a select distinct on the 21.5k repetitive logged SqlExceptions and came back with only 4 unique stacktraces, none indicating the exception occurring during handling, and none within loops of any sort. 2 were within Keydown handlers which triggered the Sql query code, one was within a Load handler which triggered the query, one was within a Click event.

Here are the two stacktraces, excepting the client code, FWIW:

at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()
at System.Data.SqlClient.TdsParser.ConsumePreLoginHandshake(Boolean encrypt, Boolean trustServerCert, Boolean& marsCapable)
at System.Data.SqlClient.TdsParser.Connect(ServerInfo serverInfo, SqlInternalConnectionTds connHandler, Boolean ignoreSniOpenTimeout, Int64 timerExpire, Boolean encrypt, Boolean trustServerCert, Boolean integratedSecurity, SqlConnection owningObject)
at System.Data.SqlClient.SqlInternalConnectionTds.AttemptOneLogin(ServerInfo serverInfo, String newPassword, Boolean ignoreSniOpenTimeout, Int64 timerExpire, SqlConnection owningObject)
at System.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(String host, String newPassword, Boolean redirectedUserInstance, SqlConnection owningObject, SqlConnectionString connectionOptions, Int64 timerStart)
at System.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(SqlConnection owningObject, SqlConnectionString connectionOptions, String newPassword, Boolean redirectedUserInstance)
at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, Object providerInfo, String newPassword, SqlConnection owningObject, Boolean redirectedUserInstance)
at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection)
at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnection owningConnection, DbConnectionPool pool, DbConnectionOptions options)
at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject)
at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject)
at System.Data.ProviderBase.DbConnectionPool.GetConnection(DbConnection owningObject)
at System.Data.ProviderBase.DbConnectionFactory.GetConnection(DbConnection owningConnection)
at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)
at System.Data.SqlClient.SqlConnection.Open()

And #2

at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadSniError(TdsParserStateObject stateObj, UInt32 error)
at System.Data.SqlClient.TdsParserStateObject.ReadSni(DbAsyncResult asyncResult, TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()
at System.Data.SqlClient.TdsParserStateObject.ReadBuffer()
at System.Data.SqlClient.TdsParserStateObject.ReadByte()
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(DbAsyncResult result, String methodName, Boolean sendToPipe)
at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()   
1

There are 1 answers

4
WozzeC On BEST ANSWER

I am going to go out on a limb here and see if this might be the issue.

  1. You never increase your retry counter. (This is not likely the main issue)

  2. If someone press retry the retry value is set to true. This value is never again set to false. So if the retry works the second time it will loop infinitely until it fails and the user can select cancel.