.NET Debugging Demos Lab 2: Crash - Walkthrough

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

  1. Browse to the Reviews page , you should see a couple of bogus reviews for BuggyBits
  2. Click on the Refresh button in the reviews page. This will crash the web host process (iisexpress.exe)

Examine the event logsPermalink

  1. 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 Files\IIS Express\iisexpress.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\tferrand\source\repos\BuggyBits\BuggyBits\Models\Review.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

  1. Browse to the reviews page again, but don’t click refresh

  2. 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

  3. 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

  1. 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.

  2. 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

  1. 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+0x21

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

  2. Examine the exception thrown

     !pe

    Note: !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

  3. 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).

  4. 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

  1. 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_Quote and String.op_Inequality which 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.

Have fun debugging, Tess

posted @ 2021-05-28 20:57  特洛伊-Micro  阅读(88)  评论(0)  编辑  收藏  举报