If broken it is, fix it you should

Using the powers of the debugger to solve the problems of the world - and a bag of chips    by Tess Ferrandez, ASP.NET Escalation Engineer (Microsoft)

ASP.NET 2.0 Crash case study: Unhandled exceptions

ASP.NET 2.0 Crash case study: Unhandled exceptions

Rate This
  • Comments 84

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 dateJ 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 DivideByZero exception 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 article http://support.microsoft.com/?id=911816

 

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 eventhandler 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 unhandledexception eventhandler 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…

 





  • Thank you for taking the time to write these articles.  Before reading your side, I'd never really comprehended windbg.  Your articles helped me use windbg to diagnose and solve some managed memory leaks in my code.  In previous positions, I'd used Rational Purify to find them, but windbg seems better to me for finding leaks.
  • Your blog rocks! It's indeed much better than many debugging books out there. I really like the way you present the problem and how you approach it mostly with the help of windbg. Reading your blogs has given me very good perspectives on what's under the covers.

    Please keep those coming.
  • PingBack from http://www.epocalipse.com/blog/2006/04/27/aspnet-20-unhandled-exceptions-and-lucenenet/
  • Have you ever experienced the 0xe0434f4d exit code and thought, what the heck is that!
    Tess has a nice...
  • Tess, your blog is great. It has helped me out a lot, especially this post. Keep it going!
  • This is very cool.  Thanks for your hard work putting this together!
  • This is a basic article but never the less it seems that many ASP.NET programmer don't know issue like this.

    Tess I really think that you are doing a great job in advancing the debugging operation made by ASP.NET developers.

    ASP.NET developer have to understand that they must understand the concept of debugging because sooner or later they will come into the situation that they will face a problem that have to be debugged.

    Thank you and keep the good job :)
  • I came across this post about dealing with unhandled ASP .NET exceptions on the blog of one of the Microsoft...
  • TCPView

    TCPView is a Windows program that will show you detailed listings of all TCP and UDP endpoints...
  • Awsome!!!!!!!!!!!!

    Your's indeed is the best blog on debugging I have ever come across. Please keep them coming :o)
  • unintelligible
  • Рекомендую почитать блог &amp;laquo;If broken it is, fix it you should&amp;raquo;. Детально рассматриваются различные...
  • There is a better UnhandledExceptionHandler here: http://dotnettricks.com/blogs/andrewcainblog/archive/2006/04/18/ELMAH_for_ASPNET2_0.aspx
  • Tłumaczenie rewelacyjnego tekstu Tess Ferrandez o radzeniu sobie z wyjątkami, kt&#243;re nie sa tak do końca oczywiste i co najgorsze są przed nami ukryte.
  • The following links to .NET resources have been collated over time with the assistance of

    colleagues.&amp;nbsp;...
Page 1 of 6 (84 items) 12345»
Leave a Comment
  • Please add 2 and 4 and type the answer here:
  • Post