Ricorrente caso di Stack Overflow

  • Article

L’applicazione ASP.NET in questione andava in crash di sovente con conseguente perdita di login e di sessione degli utenti collegati. Nell’EventLog veniva registrato il tipico messaggio di errore:

 Error ID: 1009
A process serving application pool %1 was terminated unexpectedly. The process ID was %2. The process exit code was '0x%3.

La causa di tale problema sarebbe stata molto difficile, se non impossibile, da indagare se non tramite l’uso di un debugger.

Usando i Debugging Tools for Windows si può attaccare il debugger in crash mode al workerprocess usando adplus con i seguenti switch:

 adplus -crash -pn w3wp.exe

Il debugger si metterà in ascolto sul processo intercettando l’eccezione non gestita e dumpando la memoria su disco.

Per questo post ho creato un esempietto di codice ad hoc per simulare lo scenario.

Aprendo il dump con WinDbg e caricando la SOS come visto nei post precedenti possiamo cominciare a guardare l’elenco dei trhead presenti al momento del crash:

 0:028> !threads
ThreadCount: 9
UnstartedThread: 0
BackgroundThread: 9
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception
   7    1 1290 0207d040      8220 Enabled  07378028:07379020 0207aa38     0 Ukn
  22    2 2288 02084b00      b220 Enabled  00000000:00000000 0207aa38     0 MTA (Finalizer)
  25    3 1f50 020ae080    80a220 Enabled  00000000:00000000 0207aa38     0 MTA (Threadpool Completion Port)
  26    4 11cc 020aec50      1220 Enabled  00000000:00000000 0207aa38     0 Ukn
  27    5 1598 020e3098   180b220 Enabled  0b29304c:0b294fe8 0207aa38     0 MTA (Threadpool Worker)
  28    6 22a8 020ec5c0   180b220 Disabled 0f25afd4:0f25afe8 020af2f8     1 MTA (Threadpool Worker) System.StackOverflowException (072400a4) (nested exceptions)
  29    7  f80 020f1390   180b220 Enabled  13240120:13240fe8 0207aa38     0 MTA (Threadpool Worker)
  30    8 20bc 020f1760   180b220 Enabled  00000000:00000000 0207aa38     0 MTA (Threadpool Worker)
  15    9  f20 02105918   880a220 Enabled  00000000:00000000 0207aa38     0 MTA (Threadpool Completion Port)

 rker) System.StackOverflowException (072400a4) (nested exceptions)
  29    7  f80 020f1390   180b220 Enabled  13240120:13240fe8 0207aa38     0 MTA (Threadpool Worker)
  30    8 20bc 020f1760   180b220 Enabled  00000000:00000000 0207aa38     0 MTA (Threadpool Worker)
  15    9  f20 02105918   880a220 Enabled  00000000:00000000 0207aa38     0 MTA (Threadpool Completion Port)

Si vede subito che il trhead 28 ha generato una System.StackOverflowException.

Possiamo dunque andarne ad analizzare lo stack. Prima ci posizioniamo sul thread 28 col comando ~28s e poi dumpiamo il managed stack col comando !clrstack:

 0:028> ~28s
eax=ffffffff ebx=00000000 ecx=60865860 edx=0a53ff09 esi=00000001 edi=020ec974
eip=76c008ff esp=02d23448 ebp=02d234a8 iopl=0         nv up ei ng nz na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000284
kernel32!TerminateProcess:
76c008ff 8bff            mov     edi,edi0:028> !clrstack
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for mscorwks.dll - 
PDB symbol for mscorwks.dll not loaded
OS Thread Id: 0x22a8 (28)
ESP       EIP     
02d23468 76c008ff [FaultingExceptionFrame: 02d23468] 
02d23a1c 76c008ff [HelperMethodFrame: 02d23a1c] 
02d23a74 01940976 _Default.LogException()
02d23aac 019408ef _Default.GlobalExceptionHandler()
02d23ae0 019409a5 _Default.LogException()
02d23b90 019408ef _Default.GlobalExceptionHandler()
[...cutting... ]
02d4e8a8 019409a5 _Default.LogException()
02d4e958 019408ef _Default.GlobalExceptionHandler()
02d4e98c 019409a5 _Default.LogException()
02d4ea3c 019408ef _Default.GlobalExceptionHandler()
02d4ea70 01940881 _Default.Button1_Click(System.Object, System.EventArgs)
02d4eb28 54b49ec8 System.Web.UI.WebControls.Button.OnClick(System.EventArgs)
02d4eb40 54b49d2f System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)
02d4eb58 54b49f6b System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)
02d4eb60 54445d9e System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)
02d4eb6c 54445cf5 System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)
02d4eb80 54457f1e System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
02d4ecd8 544577a4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
02d4ed10 544576d1 System.Web.UI.Page.ProcessRequest()
02d4ed48 54457666 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
02d4ed54 54457642 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
02d4ed68 01940206 ASP.default_aspx.ProcessRequest(System.Web.HttpContext)
02d4ed78 5445db16 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
02d4edac 5443132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
02d4edec 54a2531f System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
02d4edf0 54a1b704 [InlinedCallFrame: 02d4edf0] 
02d4ee90 54a0613d System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
02d4ef00 54ada7a2 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
02d4ef04 54ada58f [InlinedCallFrame: 02d4ef04] 
02d4f458 013722e4 [NDirectMethodFrameStandalone: 02d4f458] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
02d4f468 54ada839 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
02d4f4ec 54ada58f System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
02d4f5ec 013722e4 [ContextTransitionFrame: 02d4f5ec]

A dire il vero sopra riporto solo parte dello stack, tagliando la parte che si ripete uguale a se stessa per decine di volte [..cutting..].

Si nota subito la ricorrenza consistente nelle chiamate alle funzioni:

_Default.GlobalExceptionHandler()

e

_Default.LogException()

 

In pratica succede quanto segue:

- l’applicazione genera un’eccezione che viene intercettata ed inviata alla routine di gestione delle eccezioni.

- tale routine elabora l’eccezione e la invia poi ad un’altra routine che la logga.

- in quest’ultima routine si genera un seconda eccezione (la scrittura del log non va a buon fine) e tale eccezione finisce nuovamente nel global exception handler.

- quest’ultimo elabora ancora l’eccezione inviandola nuovamente al logger che, loggandola, incappa nuovamente nell’errore

- il ciclo si ripete all’infinito e lo stack si riempie.

Lo stack da me mostrato, generato con il mio codice di esempio qui sotto e contenente solo due funzioni ricorrenti, è in verità molto più semplice di quello che avveniva nell’applicazione reale, ma il concetto è il medesimo.

 
Partial Class _Default
    Inherits System.Web.UI.Page

    Protected Sub Button1_Click(ByVal sender As Object, ByVal e As System.EventArgs) Handles Button1.Click
        Try
            Throw New System.Exception

        Catch ex As Exception
            Call GlobalExceptionHandler()
        End Try
    End Sub
    Private Sub GlobalExceptionHandler()
        Try
            'do work
            Call LogException()

        Catch ex As Exception
            GlobalExceptionHandler()
        End Try
    End Sub

    Private Sub LogException()
        Try
            'do work
            Throw New System.Exception

        Catch ex As Exception
            GlobalExceptionHandler()
        End Try

    End Sub
End Class

 

Occorre dunque evitare che, all’interno del gestore di eccezioni, vengano generate eccezioni gestite con la medesima routine in modo da spezzare la ricorrenza infinita.

Seppure il concetto sembri banale, devo constatare che problemi analoghi accadono abbastanza di frequente. E’ segno dunque di quanto sia facile commettere sviste di questo tipo.

Il problema che ne consegue è poi piuttosto subdolo: ovviamente non si riproduce mai in fase di developing e testing, e tende poi a presentarsi randomicamente in produzione quando per puro caso le due eccezioni si verificano contemporaneamente.

Alla prossima

Stefano