https://www.tessferrandez.com/blog/2008/02/08/net-debugging-demos-lab-2-walkthrough.html
Hi all,
I realize that you probably haven’t all had a chance to look at the Crash lab yet, considering I just published it on Friday but here is the review for it. I have to say that considering the amount of downloads for the Buggy Bits app I am a bit surprised with the lack of questions about the labs. Perhaps they were too easy, or perhaps people just haven’t had the time to go through them yet… either case, feel free to ask questions or comment on the labs, even questions that aren’t directly related to the labs are welcome. My comments and answers are shown inline.
I will be publishing Lab 3 which will be a memory lab later this week.
Reproduce the problemPermalink
- Browse to the Reviews page , you should see a couple of bogus reviews for BuggyBits
- Click on the Refresh button in the reviews page. This will crash the web host process (iisexpress.exe)
Examine the event logsPermalink
- Open the Application and System event logs, the information in the event logs will differ based on the OS and web server you are running. Among other events you may have a System Event looking something like this
Update 2021: In later years - the descriptions here have gotten a bit more descriptive
Event Type: Warning
Event Source: W3SVC
Event Category: None
Event ID: 1009
Date: 2008-02-08
Time: 10:12:06
User: N/A
Computer: MYMACHINE
Description:
A process serving application pool 'DefaultAppPool' terminated unexpectedly. The process id was '4592'.
The process exit code was '0xe0434f4d'.
For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.
- What events do you see?
In the application log I see the following two events
Application Error 1000 (100) Faulting application name: iisexpress.exe, version: 10.0.19041.1, time stamp: 0x0cefd54e Faulting module name: unknown, version: 0.0.0.0, time stamp: 0x00000000 Exception code: 0xc0000005 Fault offset: 0x00007ffcfceafd84 Faulting process id: 0x4844 Faulting application start time: 0x01d6fadfef7e61f6 Faulting application path: C:Program FilesIIS Expressiisexpress.exe Faulting module path: unknown Report Id: 28263494-1df7-467c-8817-7f931555a0a4 Faulting package full name: Faulting package-relative application ID:.NET Runtime 1026 Application: iisexpress.exe CoreCLR Version: 4.700.20.56602 .NET Core Version: 3.1.11 Description: The process was terminated due to an unhandled exception. Exception Info: System.NullReferenceException: Object reference not set to an instance of an object. at BuggyBits.Models.Review.Finalize() in C:Users ferrandsource eposBuggyBitsBuggyBitsModelsReview.cs:line 38 - What does the exit code 0xe0434f4d mean?
0xe0434f4d is the native exception code for .NET exceptions, any .net exception will be translated into 0xe0434f4d, whether it is a SQLException, NullReferenceException or a FileNotFoundException.
- Can you tell from the event logs what it was that caused the crash?
In this case as mentioned above, the 2nd application event log entry gives it away completely. The process crashed because there was an unhandled exception on the finalizer thread when finalizing a Review object.
Get a memory dumpPermalink
- Browse to the reviews page again, but don’t click refresh
-
Run procdump with -e
procdump64.exe -ma -e iisexpress.exe- What is the debugger waiting for? Hint: Check the procdump help for -e
A 2nd chance (unhandled) exception
- What is the debugger waiting for? Hint: Check the procdump help for -e
- Reproduce the issue by clicking on the refresh button in the reviews page and watch the procdump window to verify if it captures a dump
Open the dump in windbgPermalink
-
Open the dump file in windbg (file/open crash dump).
Note: if you throw an exception (.net or other) you have a chance to handle it in a try/catch block. The first time it is thrown it becomes a 1st chance exception and is non-fatal. If you don’t handle the exception it will become a 2nd chance exception (unhandled exception) and any 2nd chance exceptions will terminate the process.
-
Set up the symbol path and load sos (see the setup instructions for more info)
In a crash dump, hte active thread is the one that caused the exceptions (since the dump is triggered on an exception).
- Which thread is active when you open the dump? Hint: check the command bar at the bottom of the windbg window.
In my dump the active thread is thread 37 - which we can see both from the prompt and from the . in the ~ (threads output) indicating the active thread
0:037> ~ ... 35 Id: acdc.9e28 Suspend: 0 Teb: 00000059`74602000 Unfrozen "" 36 Id: acdc.a81c Suspend: 0 Teb: 00000059`74604000 Unfrozen "" . 37 Id: acdc.6dd0 Suspend: 0 Teb: 00000059`74606000 Unfrozen "" 38 Id: acdc.8f30 Suspend: 0 Teb: 00000059`74608000 Unfrozen ...
Examine the call stacks and the exceptionPermalink
-
Examine the native and managed call stacks.
kb 2000 !clrstack-
What type of thread is it?
It’s the finalizer thread
0:037> k 200 # Child-SP RetAddr Call Site 00 00000059`75afec70 00007ffb`df306619 KERNELBASE!RaiseException+0x69 01 00000059`75afed50 00007ffb`df30664b coreclr!NakedThrowHelper2+0x9 02 00000059`75afed80 00007ffb`df306655 coreclr!NakedThrowHelper_RspAligned+0x1e 03 00000059`75aff2a8 00007ffb`801ac694 coreclr!NakedThrowHelper_FixRsp+0x5 04 00000059`75aff2b0 00007ffb`df306b16 0x00007ffb`801ac694 05 00000059`75aff310 00007ffb`df2a8b17 coreclr!FastCallFinalizeWorker+0x6 06 00000059`75aff340 00007ffb`df2a89f2 coreclr!MethodTable::CallFinalizer+0x97 07 (Inline Function) --------`-------- coreclr!CallFinalizer+0x3d 08 (Inline Function) --------`-------- coreclr!FinalizerThread::DoOneFinalization+0x3d 09 00000059`75aff380 00007ffb`df2a8417 coreclr!FinalizerThread::FinalizeAllObjects+0xda 0a 00000059`75aff470 00007ffb`df2a92e2 coreclr!FinalizerThread::FinalizerThreadWorker+0x97 0b (Inline Function) --------`-------- coreclr!ManagedThreadBase_DispatchInner+0xd 0c 00000059`75aff4b0 00007ffb`df2a91cf coreclr!ManagedThreadBase_DispatchMiddle+0x7e 0d 00000059`75aff5d0 00007ffb`df205f7a coreclr!ManagedThreadBase_DispatchOuter+0xaf 0e (Inline Function) --------`-------- coreclr!ManagedThreadBase_NoADTransition+0x28 0f (Inline Function) --------`-------- coreclr!ManagedThreadBase::FinalizerBase+0x28 10 00000059`75aff670 00007ffb`df2f335a coreclr!FinalizerThread::FinalizerThreadStart+0x7a 11 00000059`75aff790 00007ffc`7f0a7034 coreclr!Thread::intermediateThreadProc+0x8a 12 00000059`75aff850 00007ffc`8031d0d1 kernel32!BaseThreadInitThunk+0x14 13 00000059`75aff880 00000000`00000000 ntdll!RtlUserThreadStart+0x210:037> !clrstack OS Thread Id: 0x6dd0 (37) Child SP IP Call Site 0000005975AFEDB0 00007ffc7e08d759 [FaultingExceptionFrame: 0000005975afedb0] 0000005975AFF2B0 00007ffb801ac694 BuggyBits.Models.Review.Finalize() 0000005975AFF600 00007ffbdf306b16 [DebuggerU2MCatchHandlerFrame: 0000005975aff600] -
What is this thread doing?
It’s finalizing a Review object.
-
-
Examine the exception thrown
!peNote: !pe/!PrintException will print out the current exception being thrown on this stack if no parameters are given
-
What type of exception is it?
A NullReferenceException in the Finalize() method - NOTE: Since I got this at once - I don’t have to go through the subsequent steps
0:037> !pe Exception object: 000001ee873a77f8 Exception type: System.NullReferenceException Message: Object reference not set to an instance of an object. InnerException: <none> StackTrace (generated): SP IP Function 0000005975AFF2B0 00007FFB801AC694 BuggyBits!BuggyBits.Models.Review.Finalize()+0x44 StackTraceString: <none> HResult: 80004003
-
-
If your exception was re-thrown, look at the objects on the stack to find the address of the original exception
!dso- What is the address of the original exception?
Hint: Look at your previous pe output to see the address of the re-thrown exception. Compare this to the addresses of the objects on the stack. You should have multiple exceptions, a few with the re-thrown exception address but one of the bottommost exceptions will be the original one (look for one with a different address).
-
Print out the original exception and look at the information and the call stack
!pe <original exception address>- In what method is the exception thrown?
- What object is being finalized?
Note: you could actually have gotten this information by dumping out the _exceptionMethodString of the re-thrown exception as well, but with !pe of the original exception you get the information in a cleaner way.
-
Normally exceptions thrown in ASP.NET are handled with the global exception handler and an error page is shown to the user. Why did this not occur here? Why did it cause a crash?
The global exception handler for ASP.NET only handles exceptions thrown when processing a request. In this case the exception is thrown on the finalizer which means that there is no user there to see the exception and therefore there is no one to show the error page to.
In 1.1. and if you use legacy exception handling in 2.0, exceptions on the finalizer are non-fatal, i.e. they will not crash the process, instead the finalizer would just stop finalizing the current object. This is very dangerous since this means that you may not process code that releases native objects and thus you may end up with a memory leak that is very hard to troubleshoot or other resource leaks like connection leaks etc. All unhandled exceptions on the finalizer thread should be investigated and taken seriously.
Examine the code for verificationPermalink
-
Open the code for the Review class to find the destructor/finalizer for the Review class
-
which line or method could have caused the exception
The only potential line that could NullRef here is the Quote.ToString() if Quote is null
~Review() { if (Quote.ToString() != string.Empty) Quote = null; }
-
As an extra exercise you can also examine the disassembly of the function to try to pinpoint better where in the function the exception is caused
!u <IP shown in the exception stack>
Our IP is 00007FFB801AC694
0:037> !u 00007FFB801AC694
Normal JIT generated code
BuggyBits.Models.Review.Finalize()
Begin 00007FFB801AC650, size bd
00007ffb`801ac650 55 push rbp
00007ffb`801ac651 4883ec50 sub rsp,50h
00007ffb`801ac655 488d6c2450 lea rbp,[rsp+50h]
00007ffb`801ac65a 33c0 xor eax,eax
00007ffb`801ac65c 8945fc mov dword ptr [rbp-4],eax
00007ffb`801ac65f 488945f0 mov qword ptr [rbp-10h],rax
00007ffb`801ac663 488945e8 mov qword ptr [rbp-18h],rax
00007ffb`801ac667 488965d0 mov qword ptr [rbp-30h],rsp
00007ffb`801ac66b 48894d10 mov qword ptr [rbp+10h],rcx
00007ffb`801ac66f 833d22346eff00 cmp dword ptr [00007ffb`7f88fa98],0
00007ffb`801ac676 7405 je 00007ffb`801ac67d
00007ffb`801ac678 e8e310285f call coreclr!JIT_DbgIsJustMyCode (00007ffb`df42d760)
00007ffb`801ac67d 90 nop
00007ffb`801ac67e 90 nop
00007ffb`801ac67f 488b4d10 mov rcx,qword ptr [rbp+10h]
00007ffb`801ac683 e8b8eeffff call 00007ffb`801ab540 (BuggyBits.Models.Review.get_Quote(), mdToken: 0000000006000015)
00007ffb`801ac688 488945f0 mov qword ptr [rbp-10h],rax
00007ffb`801ac68c 488b4df0 mov rcx,qword ptr [rbp-10h]
00007ffb`801ac690 488b45f0 mov rax,qword ptr [rbp-10h]
>>> 00007ffb`801ac694 488b00 mov rax,qword ptr [rax]
00007ffb`801ac697 488b4040 mov rax,qword ptr [rax+40h]
00007ffb`801ac69b ff5008 call qword ptr [rax+8]
00007ffb`801ac69e 488945e8 mov qword ptr [rbp-18h],rax
00007ffb`801ac6a2 48ba48103ab7ef010000 mov rdx,1EFB73A1048h
00007ffb`801ac6ac 488b12 mov rdx,qword ptr [rdx]
00007ffb`801ac6af 488b4de8 mov rcx,qword ptr [rbp-18h]
00007ffb`801ac6b3 e8407e63ff call 00007ffb`7f7e44f8 (System.String.op_Inequality(System.String, System.String), mdToken: 00000000060006EF)
00007ffb`801ac6b8 8945e4 mov dword ptr [rbp-1Ch],eax
00007ffb`801ac6bb 8b4de4 mov ecx,dword ptr [rbp-1Ch]
If we look at the disassembly and compare it to the method above we find that the exception address falls between
Review.get_QuoteandString.op_Inequalitywhich matches up to if(quote.ToString()!= string.Empty)
Btw, the reason that quote was null is because Clear() sets it to null. The proper way to resolve this issue would have been to not have a finalizer (since we don’t really need one given that we don’t have to clean up any native resources) or at the very least we should have called GC.SuppressFinalize() in the Clear() method.
Related postsPermalink
- ASP.NET 2.0 Crash case study: Unhandled exceptions
- What on earth caused my process to crash?
- .Net exceptions - Tracking down where in the code the exceptions ocurred
Have fun debugging, Tess