ASP.NET 2.0 Crash case study: Unhandled exceptions
For a long time all my case studies have been on 1.1. it’s time to venture out in 2.0 land and look at what may seem like a 2.0 specific issue.
I say “may seem” because this case study will only directly crash if you are using 2.0, but as you’ll learn later the problem existed in 1.1 and 1.0, it was just way harder to track down.
Problem description
Once in a while ASP.NET crashes and we see events in the system event log like this one
Event Type: Warning
Event Source: W3SVC
Event Category: None
Event ID: 1009
Date: 2006-04-25
Time: 09:41:22
PM User: N/A
Computer: SUBSPACE1
Description:
A process serving application pool 'ASP.NET V2.0' terminated unexpectedly. The process id was ‘1732’. The process exit code was ‘0xe0434f4d’.
Or this one
Event Type: Warning
Event Source: W3SVC
Event Category: None
Event ID: 1011
Date: 2006-04-25
Time: 09:41:22
User: N/A
Computer: SUBSPACE1
Description:
A process serving application pool 'ASP.NET V2.0' suffered a fatal communication error with the World Wide Web Publishing Service. The process id was '6256'. The data field contains the error number.
And in the application event log we get a pretty cryptic error message like this one
Event Type: Error
Event Source: .NET Runtime 2.0 Error Reporting
Event Category: None
Event ID: 5000
Date: 2006-04-25
Time: 09:41:20
User: N/A
Computer: SUBSPACE1
Description:
EventType clr20r3, P1 w3wp.exe, P2 6.0.3790.1830, P3 42435be1, P4 app_code.pn5mfdcr, P5 0.0.0.0, P6 444dcf44, P7 5, P8 5, P9 system.dividebyzeroexception, P10 NIL.
Initial thoughts
Ok, so what do we know about the issue? We know that asp.net terminated unexpectedly, and that right before this we got a System.DivideByZeroException. We also know that the process exit code was 0xe0434f4d whatever that means, hmm…
Usually when you get a stopped unexpectedly error message the exit code will be the type of exception that caused the crash. For example a 0xC0000005 means you got a second chance access violation, 0x800703e9 means you suffered a StackOverflowException but what about 0xe0434f4d?
0xe0434f4d is the exception code for CLR (.net) exceptions, so any managed exception like a NullReferenceException or InvalidOperationException or SQLException, basically all managed exception are natively referred to as 0xe0434f4d. In this case, if we look closer at the application event log entry we can see that it is in fact a System.DivideByZero exception.
Trivia: Just a piece of info of no particular value that you might want to pull out of pocket on your next date 0xe0434f4d or at least 43 4f 4d are the ASCII values for the letters COM.
But hey now… should a .net exception cause the asp.net process to crash??? If you divide by zero in your page and don’t have a try catch block around it, surely you will get one of those “nice” white and yellow error pages saying that an exception occurred on your page, but the process doesn’t just exit.
The answer is yes, you will get one of those pages because the asp.net global error handler will eventually catch your exception, format it for you and print it out on the screen. But what happens if it is not on an asp.net request, so there is no-one to feedback the exception to? It’s the old paradox: If a tree falls in the forest and nobody is there, does it still make a sound?
In 1.0 and 1.1 it didn’t. For example if you throw an exception in a piece of code called on a timer, or use QueueUserWorkItem and throw an exception in code executing there, or otherwise throw exceptions in code that is not running inside the context of an asp.net request, the framework will swallow the exception and continue. Or rather it will stop that thread of execution but it won’t die.
Doesn’t sound all that bad right? Really???
That thread could have been doing anything, and we will never be the wiser that it died. It could have been holding a lock of some sort, or it could have been in the middle of cleaning up resources, or really a number of different things that will now never happen, but that may immediately or eventually have really bad side effects like hangs or crashes or memory issues, but the exception will be long gone so we cant figure out what it was.
The policy for unhandled exceptions was changed in ASP.NET 2.0 to the default for .net which is a process exit. This can be changed back by adding the following to the aspnet.config in the frameworks directory, but I wouldn’t recommend it without putting in some preventive measures to take care of potential unhandled exceptions on non ASP.NET threads.
<configuration>
<runtime>
<legacyUnhandledExceptionPolicy enabled="true" />
</runtime>
</configuration>
Troubleshooting the issue
The main task here is to find out where this DivideByZeroException is coming from and why it occurred so there are two ways to figure this out (short of complete code inspection).
Strategy #1 – logging the exception
The first way, and this is the way I would probably recommend, is to create an UnhandledExceptionHandler to log the exception along with its stack trace in the event log as shown in this KB article
You add the handler like this to the web.config:
<system.web>
<httpModules>
<add type="WebMonitor.UnhandledExceptionModule, <strong name>" name="UnhandledExceptionModule"/>
</httpModules>
...
</system.web>
And it hooks an event handler up to the UnhandledException event of the current app domain.
You don’t actually need to strong name it and add it to the GAC, however if you plan it in multiple applications you should to avoid for the dll being loaded multiple times.
Now the next time you get one of these unhandled exceptions, the process will still exit (unless you change the unhandled exception policy), but you have a very good chance of fixing the issue.
The event for the exception in this particular sample looks like this…
Event Type: Error
Event Source: ASP.NET 2.0.50727.0
Event Category: None
Event ID: 0
Date: 2006-04-25
Time: 09:41:20
User: N/A
Computer: SUBSPACE1
Description:
UnhandledException logged by UnhandledExceptionModule.dll:
appId=/LM/w3svc/1/ROOT/CrashMe
type=System.DivideByZeroException
message=Attempted to divide by zero.
stack=
at MyFinalizerClass.Finalize()
.
Bingo!!! So the exception occurs in MyFinalizerClass.Finalize() in the CrashMe application.
In fact the code for the finalizer for this class looks like this, so it is pretty obvious what caused it, and our work here is done…
~MyFinalizerClass()
{
int i = 0;
int j = 9;
i = j / i;
}
Setting up an UnhandledException handler like this is not limited to 2.0. You can absolutely do this in 1.1 as well to determine if you are throwing any unhandled exceptions. The only modification you need to do to the code outlined in the article is to choose a different dll to gather the version from. A prime candidate for this would be mscorlib.dll.
Strategy #2 – debugging with windbg
If you have read any of my previous posts you know I have a special place in my heart for debugging. If you don’t have an unhandled exception event handler you can still find out what the exception was by running adplus in crash mode to generate dumps when the process exits.
In this particular case doing this will result in the following files being generated.
C:\debuggers\Crash_Mode__Date_04-25-2006__Time_10-11-3030>dir
Volume in drive C has no label.
Volume Serial Number is 30D7-F806
Directory of C:\debuggers\Crash_Mode__Date_04-25-2006__Time_10-11-3030
2006-04-25 10:12 <DIR> .
2006-04-25 10:12 <DIR> ..
2006-04-25 10:11 4 404 ADPlus_report.txt
2006-04-25 10:11 <DIR> CDBScripts
2006-04-25 10:11 9 420 059 PID-3368__W3WP.EXE__1st_chance_IntegerDivide__mini_12D8_2006-04-25_10-11-51-487_0D28.dmp
2006-04-25 10:12 108 142 158 PID-3368__W3WP.EXE__1st_chance_Process_Shut_Down__full_12D8_2006-04-25_10-12-02-440_0D28.dmp
2006-04-25 10:12 108 294 606 PID-3368__W3WP.EXE__2nd_chance_NET_CLR__full_12D8_2006-04-25_10-11-54-690_0D28.dmp
2006-04-25 10:12 35 324 PID-3368__W3WP.EXE__Date_04-25-2006__Time_10-11-3030.log
2006-04-25 10:11 9 014 Process_List.txt
6 File(s) 225 905 565 bytes
3 Dir(s) 4 592 435 200 bytes free
So at 10-11-51 a 1st chance IntegerDivide exception occurred, followed by a 2nd chance .NET exception (2nd chance meaning that it wasn’t handled), and finally this was followed by a process shutdown.
Concentrating on the 2nd chance exception dump and loading up sos.dll from the framework directory
0:020> .load C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\sos.dll
We can run !threads to give us a list of the threads along with info about which thread the exception occurred on (in this case thread 20, the finalizer thread).
0:020> !threads
ThreadCount: 7
UnstartedThread: 0
BackgroundThread: 7
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
PreEmptive GC Alloc Lock
ID OSID ThreadOBJ State GC Context Domain Count APT Exception
16 1 c20 000b9778 3808220 Enabled 00000000:00000000 000fddc0 1 Ukn (Threadpool Worker)
20 2 16d8 000e3bd0 b220 Enabled 0242ab08:0242bf94 000caad8 0 MTA (Finalizer) System.DivideByZeroException (02428f60)
21 3 b2c 000fa588 80a220 Enabled 00000000:00000000 000caad8 0 MTA (Threadpool Completion Port)
22 4 16c0 000fd690 1220 Enabled 00000000:00000000 000caad8 0 Ukn
14 6 1570 0014a970 880a220 Enabled 00000000:00000000 000caad8 0 MTA (Threadpool Completion Port)
23 7 1b44 00145178 180b220 Enabled 00000000:00000000 000caad8 0 MTA (Threadpool Worker)
24 5 bac 0014a5b0 880b220 Enabled 00000000:00000000 000caad8 0 MTA (Threadpool Completion Port)
So from this we know that we are looking at an exception happening during finalization.
Since this dump was triggered by the exception this will also be the active thread when you load up the dump.
If we look at the native and managed callstack it doesn’t really bring us any closer to the solution…
0:020> kb 2000
ChildEBP RetAddr Args to Child
01eaf9fc 79f97065 e0434f4d 00000001 00000001 kernel32!RaiseException+0x53
01eafa5c 7a05b941 02428f60 00000000 00000000 mscorwks!RaiseTheExceptionInternalOnly+0x226
01eafa70 7a05b9b2 02428f60 00000000 01eafb88 mscorwks!RaiseTheException+0x4c
01eafa98 7a05b9ea 00000000 000e3bd0 4914714b mscorwks!RaiseTheException+0xbe
01eafac4 7a05b9f5 02428f60 00000000 7a0e0701 mscorwks!RealCOMPlusThrow+0x37
01eafad0 7a0e0701 02428f60 7740e5f5 7a36a738 mscorwks!RealCOMPlusThrow+0xa
01eafc00 7a0e16e4 00000000 01eafc38 01eafca8 mscorwks!Thread::RaiseCrossContextException+0x63
01eafcb4 79f3a09c 000fddc0 79f3a0a1 01eafeb4 mscorwks!Thread::DoADCallBack+0x25a
01eafcd0 79f3581e 01eafeb4 79f3ab82 000fddc0 mscorwks!Thread::UserResumeThread+0xf3
01eafcd8 79f3ab82 000fddc0 79f3abb0 01eafd08 mscorwks!ManagedThreadBase::FinalizerAppDomain+0x26
01eafd34 79f350ea 000e3bd0 00000000 01eafd5b mscorwks!SVR::CreateGCHeap+0x163
01eafdb0 79f3500e 00000000 00000000 01eafe6c mscorwks!SVR::CreateGCHeap+0x204
01eafdc8 79ecb4a4 01eafeb4 00000000 00000001 mscorwks!SVR::GCHeap::FinalizerThreadWorker+0xe7
01eafdd8 79ecb442 01eafeb4 01eafe60 79f93fe6 mscorwks!Thread::UserResumeThread+0xfb
01eafe6c 79ecb364 01eafeb4 7740e0c9 00000000 mscorwks!Thread::DoADCallBack+0x355
01eafea8 79ed5e8b 01eafeb4 00000000 000fddc0 mscorwks!Thread::DoADCallBack+0x541
01eafed0 79ed5e56 79f34f4a 00000008 79f6fd87 mscorwks!ManagedThreadBase_NoADTransition+0x32
01eafedc 79f6fd87 79f34f4a 7740e175 00000000 mscorwks!ManagedThreadBase::FinalizerBase+0xb
01eaff14 79ecb00b 00000000 00000000 00000000 mscorwks!SVR::GCHeap::FinalizerThreadStart+0xbb
01eaffb8 77e66063 000e4390 00000000 00000000 mscorwks!Thread::intermediateThreadProc+0x49
01eaffec 00000000 79ecafc5 000e4390 00000000 kernel32!BaseThreadStart+0x34
0:020> !clrstack
OS Thread Id: 0x16d8 (20)
ESP EIP
01eafaac 77e55dea [GCFrame: 01eafaac]
01eafb14 77e55dea [GCFrame: 01eafb14]
01eafd14 77e55dea [GCFrame: 01eafd14]
But from the !threads output we get the address of the exception (02428f60) and we can take a deeper look…
0:020> !do 02428f60
Name: System.DivideByZeroException
MethodTable: 7915e020
EEClass: 791e97f8
Size: 72(0x48) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fa3e0 40000b5 4 System.String 0 instance 02429e78 _className
79109208 40000b6 8 ...ection.MethodBase 0 instance 00000000 _exceptionMethod
790fa3e0 40000b7 c System.String 0 instance 0242a18c _exceptionMethodString
790fa3e0 40000b8 10 System.String 0 instance 02429fb4 _message
79113dfc 40000b9 14 ...tions.IDictionary 0 instance 00000000 _data
790fa9e8 40000ba 18 System.Exception 0 instance 00000000 _innerException
790fa3e0 40000bb 1c System.String 0 instance 00000000 _helpURL
790f9c18 40000bc 20 System.Object 0 instance 00000000 _stackTrace
790fa3e0 40000bd 24 System.String 0 instance 00000000 _stackTraceString
790fa3e0 40000be 28 System.String 0 instance 0242aab0 _remoteStackTraceString
790fed1c 40000bf 34 System.Int32 0 instance 0 _remoteStackIndex
790f9c18 40000c0 2c System.Object 0 instance 00000000 _dynamicMethods
790fed1c 40000c1 38 System.Int32 0 instance -2147352558 _HResult
790fa3e0 40000c2 30 System.String 0 instance 0242a3c4 _source
790fe160 40000c3 3c System.IntPtr 0 instance 0 _xptrs
790fed1c 40000c4 40 System.Int32 0 instance 0 _xcode
In particular we can dump out the _remoteStackTraceString and find out where exactly the error occurred.
0:020> !do 0242aab0
Name: System.String
MethodTable: 790fa3e0
EEClass: 790fa340
Size: 88(0x58) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: at MyFinalizerClass.Finalize()
Fields:
MT Field Offset Type VT Attr Value Name
790fed1c 4000096 4 System.Int32 0 instance 36 m_arrayLength
790fed1c 4000097 8 System.Int32 0 instance 35 m_stringLength
790fbefc 4000098 c System.Char 0 instance 20 m_firstChar
790fa3e0 4000099 10 System.String 0 shared static Empty
>> Domain:Value 000caad8:790d6584 000fddc0:790d6584 <<
79124670 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 000caad8:023d03f0 000fddc0:023d4374 <<
Voila, there we have it again… our MyFinalizerClass.Finalize()
If you want to take away just one thing from this post, it should be to be careful with the code running on non ASP.NET threads, making sure that you have proper try / catch blocks around any code that could cause an exception.
Until next time…
