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,edi

0: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