• Ntdebugging Blog

    Tracking Down a Multi-Process Deadlock

    • 9 Comments

     

    Hello, my name is Louis Shanks and my story starts off with a tricky little deadlock issue that I worked on recently. Let me set the stage by explaining the surface level symptom, and then we will get to the good stuff. Randomly when users running Vista would attempt to launch Internet Explorer nothing would happen. So they would again double-click the icon, and still nothing happened. So the users would reboot and go back to their web activities.

     

    After some basic trouble shooting it was discovered that Iexplore.exe was running multiple times and every attempt to open the browser would result in another Iexplore.exe instance.  Since no UI was ever presented I went ahead and collected a few Iexplore.exe process dumps along with a complete system dump.

     

     The process dumps didn’t prove to be terribly useful so I decided to move over to the complete memory dump.

     

    Since I knew we had multiple IExplore.exe processes running I wanted to investigate them first.

     

    0: kd>!process 0 0

     

    <snip>

    PROCESS 87289d90  SessionId: 5  Cid: 0fdc    Peb: 7ffdc000  ParentCid: 0968

        DirBase: 7d66c520  ObjectTable: a203a178  HandleCount: 205.

        Image: iexplore.exe

     

    PROCESS 861a9d90  SessionId: 5  Cid: 0d34    Peb: 7ffd9000  ParentCid: 0fdc

        DirBase: 7d66c7a0  ObjectTable: a5651a98  HandleCount: 170.

        Image: ieuser.exe

     

    PROCESS 86c175b0  SessionId: 5  Cid: 1250    Peb: 7ffd9000  ParentCid: 0968

        DirBase: 7d66c940  ObjectTable: a0853f10  HandleCount:  91.

        Image: iexplore.exe


    PROCESS 861ac7a8  SessionId: 5  Cid: 1024    Peb: 7ffde000  ParentCid: 0968

        DirBase: 7d66c620  ObjectTable: a83f7898  HandleCount:  91.

    Image: iexplore.exe
    </snip>

    I decided to just start with the first one in the list (87289d90)

     

    0: kd> !process 87289d90
        Image: iexplore.exe

        ElapsedTime                       00:24:06.666

     

    It appears this process has been around a while, so I wanted to look at the first thread in this process as it is responsible for the UI in Internet Explorer.  I am looking at this thread because the surface level problem illustrates that when we launch Iexplore.exe the UI is never displayed. Here I used the !thread command to display the specific thread.

     

            THREAD 870b6398  Cid 0fdc.16a4  Teb: 7ffdf000 Win32Thread: fd850b78 WAIT: (UserRequest) UserMode Non-Alertable

                85e86cf0  SynchronizationEvent

                85cb35e0  SynchronizationEvent

            Not impersonating

            Attached Process          87289d90       Image:         iexplore.exe

            Wait Start TickCount      10817197       Ticks: 69571 (0:00:18:05.314)

            UserTime                  00:00:00.015

            KernelTime                00:00:00.093  

     

    Based on the tick count this thread has been waiting for 18 minutes.

     

    0: kd> kvn

    # ChildEBP RetAddr  Args to Child             

    00 931208d8 81a940a1 870b6398 803d2120 870b6420 nt!KiSwapContext+0x26

    01 9312091c 81a8dacc 870b6398 00000000 00000002 nt!KiSwapThread+0x44f

    02 93120970 81bedb4f 00000002 93120aa8 00000001 nt!KeWaitForMultipleObjects+0x53d

    03 93120bfc 81bee2e3 00000002 00000001 00000000 nt!ObpWaitForMultipleObjects+0x256

    04 93120d48 81a30b3a 00000002 0027e9c4 00000001 nt!NtWaitForMultipleObjects+0xcc

    05 93120d48 77568254 00000002 0027e9c4 00000001 nt!KiFastCallEntry+0x12a

    06 0027e970 775679fc 7708c973 00000002 0027e9c4 ntdll!KiFastSystemCallRet

    07 0027e974 7708c973 00000002 0027e9c4 00000001 ntdll!NtWaitForMultipleObjects+0xc

    08 0027ea10 7608ff95 0027e9c4 0027ea38 00000000 kernel32!WaitForMultipleObjectsEx+0x11d

    09 0027ea64 773d3a46 00000028 0027eaac ffffffff USER32!RealMsgWaitForMultipleObjectsEx+0x13c

    0a 0027ea8c 773d3b7f 0027eaac ffffffff 0027eabc ole32!CCliModalLoop::BlockFn+0x97

    0b 0027eab4 774e75be ffffffff 003ddf90 0027ebc0 ole32!ModalLoop+0x5b

    0c 0027ead0 774e9294 00000000 0027ebd4 00000000 ole32!ThreadSendReceive+0x12c

    0d 0027eaf8 774e9100 0027ebc0 003d3538 0027ec1c ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x194

    0e 0027ebd8 773d3c25 003d3538 0027ecfc 0027ece4 ole32!CRpcChannelBuffer::SendReceive2+0xef

    0f 0027ebf4 773d3bd7 0027ecfc 0027ece4 003d3538 ole32!CCliModalLoop::SendReceive+0x1e

    10 0027ec6c 77403efb 003d3538 0027ecfc 0027ece4 ole32!CAptRpcChnl::SendReceive+0x73

    11 0027ecc0 76052ff4 003d3538 0027ecfc 0027ece4 ole32!CCtxComChnl::SendReceive+0x1c5

    12 0027ecd8 76053055 003e50a4 0027ede4 76052e0d RPCRT4!NdrProxySendReceive+0x43

    13 0027ece4 76052e0d 09ea0d59 0027f1fc 070001f3 RPCRT4!NdrpProxySendReceive+0xc

     

    Based on the call stack it appears this thread made an OLE call and is now waiting for some objects to signal.

     

    What is IExplore doing in this thread?  It is waiting on another process to service this OLE request.   We can find the PID of the other process by digging into the ole32 SendReceive call.

     

    I looked at the first argument:

     

    0: kd> dd 003d3538

    003d3538  77403a50 773f57b4 00000003 00000002

    003d3548  00000000 00000000 003d2ef0 003d8840

    003d3558  0038b1c0 003e05f8 77403980 00070005

     

    This gives us a pointer to another data structure that contains the information we are attempting to locate.


    0: kd> dd 003d2ef0

    003d2ef0  774ee600 003d2e70 00000d34 00000000

    003d2f00  862941fa c94cde09 55a88424 801a2601

    003d2f10  55a88424 801a2601 0000c400 00000d34

     

    Ah there it is! 0d34 is the process id servicing our OLE request.

     

    I went back and reviewed the !process 0 0 output to locate the process containing PID 0D34. I’m dumping it here.

     

    PROCESS 861a9d90  SessionId: 5  Cid: 0d34    Peb: 7ffd9000  ParentCid: 0fdc

        DirBase: 7d66c7a0  ObjectTable: a5651a98  HandleCount: 170.

        Image: ieuser.exe

     

    Ok, so the process handing this request is IEUSER.exe, which is the broker process used by Internet Explorer in Vista when running in protect mode.  This is new in Vista.

     

    More on IEUser and Protected mode can be seen at the following location:
    http://msdn.microsoft.com/en-us/library/bb250462.aspx

     

    Now I needed to dig into the IEUser.exe process to find out what it was working on causing Iexplore to wait.

     

    0: kd> !process 861a9d90 

    PROCESS 861a9d90  SessionId: 5  Cid: 0d34    Peb: 7ffd9000  ParentCid: 0fdc

        DirBase: 7d66c7a0  ObjectTable: a5651a98  HandleCount: 170.

        Image: ieuser.exe


    I discovered the thread in the ieuser.exe process working on our call from Iexplore.exe. However this thread is also waiting on access to something before it can complete.


    0: kd> kvn+200

     # ChildEBP RetAddr  Args to Child             

    00 a41b0c50 81a940a1 85ecbac0 85ecbb48 81af9920 nt!KiSwapContext+0x26

    01 a41b0c94 81a2ddc8 85ecbac0 00000000 85e18510 nt!KiSwapThread+0x44f

    02 a41b0ce8 81bf0d9f 85e18510 00000006 00000001 nt!KeWaitForSingleObject+0x492

    03 a41b0d50 81a30b3a 00000224 00000000 00000000 nt!NtWaitForSingleObject+0xbe

    04 a41b0d50 77568254 00000224 00000000 00000000 nt!KiFastCallEntry+0x12a

    05 0163e8a4 77567a0c 7708c7c4 00000224 00000000 ntdll!KiFastSystemCallRet

    06 0163e8a8 7708c7c4 00000224 00000000 00000000 ntdll!NtWaitForSingleObject+0xc

    07 0163e918 7708c732 00000224 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xbe

    08 0163e92c 747e60aa 00000224 ffffffff 00000000 kernel32!WaitForSingleObject+0x12

    09 0163e948 747e5fe0 0163ec48 00497b38 00000000 RASAPI32!ReadPhonebookFileEx+0x1a4

    0a 0163e968 747e4e9d 0163ec48 00000000 00000000 RASAPI32!ReadPhonebookFile+0x1b

    0b 0163e9a8 747e52d3 0163ec48 0048f660 0163e9e0 RASAPI32!DwEnumEntriesFromPhonebook+0x35

    0c 0163ee58 747e4fd4 0163ee9c 00000001 0048f660 RASAPI32!DwEnumEntriesInDir+0x1cc

    0d 0163f0ac 747e677e 00000001 0048f660 0163f0f4 RASAPI32!DwEnumEntriesForPbkMode+0xab

    0e 0163f0e0 76e534b9 00000000 00004180 0048f660 RASAPI32!RasEnumEntriesW+0xb0

    0f 0163f10c 76e5342a 76ecc2dc 00000000 00000000 WININET!RasEnumHelp::RasEnumHelp+0x55

    10 0163f120 76e533a3 00000001 00000000 00000001 WININET!DoConnectoidsExist+0x2b

    11 0163f14c 76e534ff 76ecf02c 76ecc2dc 00000000 WININET!GetRasConnections+0x34

    12 0163f168 76e4196e 00000000 0163f180 6ee3228c WININET!IsDialUpConnection+0xa9

    13 0163f184 76e70564 00000001 00000000 00000000 WININET!FixProxySettingsForCurrentConnection+0x31

    14 0163f1a8 6ec2db3b 00000000 0163f1bc 0163f3d4 WININET!InternetInitializeAutoProxyDll+0x6c

    15 0163f1b8 75fe9142 004884a0 00000202 0047e900 ieframe!CShdocvwBroker::StartAutoProxyDetection+0x4d

    16 0163f1d0 76054294 6ec2daf8 0163f3d8 00000001 RPCRT4!Invoke+0x2a

    17 0163f5fc 76054a49 004858d0 0046e4e0 0047e900 RPCRT4!NdrStubCall2+0x27b

    18 0163f64c 774e86d7 004858d0 0047e900 0046e4e0 RPCRT4!CStdStubBuffer_Invoke+0xa0

    19 0163f694 774e877d 0047e900 0047f968 00480b38 ole32!SyncStubInvoke+0x3c

    1a 0163f6e0 7740249e 0047e900 0047f860 004858d0 ole32!StubInvoke+0xb9

    1b 0163f7bc 774023af 0046e4e0 00000000 004858d0 ole32!CCtxComChnl::ContextInvoke+0xfa

    1c 0163f7d8 774e85df 0047e900 00000001 004858d0 ole32!MTAInvoke+0x1a

    1d 0163f808 774e8a18 d0908070 0046e4e0 004858d0 ole32!AppInvoke+0xaa

    1e 0163f8e4 774e85ef 0047e8a8 00474118 0047ebc0 ole32!ComInvokeWithLockAndIPID+0x32c

    1f 0163f930 75fe94b0 0047ebc0 08ac70b7 0047ebc0 ole32!ThreadInvoke+0x2fd

     

    I’m dumping the first parameter passed to KeWaitForSingleObject to determine the object type.

     

    0: kd> !object 85e18510

    Object: 85e18510  Type: (85484d40) Mutant

        ObjectHeader: 85e184f8 (old version)

        HandleCount: 3  PointerCount: 5

        Directory Object: 881f3030  Name: RasPbFile


    Ok, we are waiting on a Mutex named RasPbFile. The big question in your mind now is, “who owns this lock”, right?

    To determine this I’ll dump the structure for the mutex object:

     

    0: kd> dt _KMUTANT 85e18510

    nt!_KMUTANT

       +0x000 Header           : _DISPATCHER_HEADER

       +0x010 MutantListEntry  : _LIST_ENTRY [ 0x870b6564 - 0x870b6564 ]

       +0x018 OwnerThread      : 0x870b6398 _KTHREAD

       +0x01c Abandoned        : 0 ''

       +0x01d ApcDisable       : 0 ''

     

    The owner of the mutex is 870b6398. The bad news is this is the same thread I started with in the Iexplore.exe process so we’re looking at a classic deadlock scenario. Thread 870b6398 running under Iexplore.exe has made an OLE call over to the IEuser.exe broker process. The IEuser process needs the mutex owned by the thread that called it in the first place.

    This turned out to be a bug in the RasApi code, not the browser or IEuser process.  The RasAPI code was written in such a way that it would wait for an infinite period of time to gain the Mutex.

     

    0163e92c 747e60aa 00000224 ffffffff 00000000 kernel32!WaitForSingleObject+0x12

     

     The good news is that we have created hotfix 951738 to address this issue.  The official KB article is still pending.

  • Ntdebugging Blog

    Case of the Unexplained Services exe Termination

    • 9 Comments

    Hello Debuggers! This is Ron Stock from the Global Escalation Services team and I recently worked an interesting case dispatched to our team because Services.exe was terminating. Nothing good ever happens when Services.exe exits. In this particular case, client RDP sessions were forcibly disconnected from the server and the server machine was shutting down unexpectedly. This is the message encountered at the console on the server.

     

     

     

    The customer was able to trigger the crash by changing anything to do with a particular non-Microsoft service in the Services MMC (e.g. changing the Startup Type, changing the dependencies, stopping the service etc...) To protect our vendor friend, I refer to this service as FriendlyService throughout this article. We could have stopped the investigation right here and implicated the FriendlyService vendor, however as you will see, this service was merely a victim.

     

    Investigation

    When investigating a process termination, I routinely gather a process dump to start my investigation. The frustrating thing about this instance was how none of our debugging tools were generating a dump file when Services.exe terminated. I tried the usual toolset including AdPlus, ProcDump and DebugDiag to no avail. Despite the lack of data from a memory dump, I was still able to piece together a stack and attack the problem through a creative approach. Debugging is an art.

     

    First I reviewed the application log which was loaded with entries like this one.

     

    11/29/2012 04:29:05 PM  Information   HE2NTSP208       1004    Application Error  N/A Faulting application services.exe, version 5.2.3790.4455, faulting module msvcr80.dll, version 8.0.50727.6195, fault address 0x000000000001df67

     

    From the event log entry above I was able to determine the faulting module, msvcr80.dll, and the relative offset, 0x000000000001df67. This address is basically the return address of the faulting call. As you can see from the ln output below, the function name was msvcr80!wcscpy_s. As I noted above, I wasn’t able to gather a dump during process termination so I had the customer use ProcDump to snap a dump of Services.exe during normal process operation (not a crash dump).

     

    0:000> ln 00000000`78130000 + 0x000000000001df67
    (00000000`7814ded0)   msvcr80!wcscpy_s+0x97   |  (00000000`7814df80)   msvcr80!wcsncpy_s

     

    Next I needed to determine which DLLs in the Services.exe process were calling msvcr80!wcscpy_s by reviewing the import tables of the binaries loading in the process. I used the !peb command to dump out the Process Environment Block (PEB). This gave me the list of base addresses for each loaded DLL. I focused mainly on non-Microsoft binaries. To protect our vendor friends, I renamed the DLL to ThirdPartyServiceMonitor.Dll in this article.

     

    This is the output from the !peb command with the base addresses in the left column.

     

    0:000> !peb

    PEB at 000007fffffde000

        InheritedAddressSpace:    No

        ReadImageFileExecOptions: No

        BeingDebugged:            Yes

        ImageBaseAddress:         0000000100000000

        Ldr                       0000000077fa9f20

        Ldr.Initialized:          Yes

        Ldr.InInitializationOrderModuleList: 00000000000d2df0 . 00000000001a3600

        Ldr.InLoadOrderModuleList:           00000000000d2d20 . 000000000019cbc0

        Ldr.InMemoryOrderModuleList:         00000000000d2d30 . 000000000019cbd0

                Base TimeStamp                     Module

           100000000 49882047 Feb 03 04:45:27 2009 C:\WINDOWS\system32\services.exe

            77ec0000 4ecbcd57 Nov 22 10:27:03 2011 C:\WINDOWS\system32\ntdll.dll

            77d40000 49c51cdd Mar 21 11:59:09 2009 C:\WINDOWS\system32\kernel32.dll

         7ff7fc00000 45d6ccae Feb 17 03:36:46 2007 C:\WINDOWS\system32\msvcrt.dll

         7ff7fee0000 4a61f064 Jul 18 10:55:16 2009 C:\WINDOWS\system32\ADVAPI32.dll

         7ff7fd30000 4c6ba77a Aug 18 04:27:22 2010 C:\WINDOWS\system32\RPCRT4.dll

         7ff7e9c0000 4a37438e Jun 16 02:02:38 2009 C:\WINDOWS\system32\Secur32.dll

            77c20000 45e7c5c2 Mar 02 00:35:46 2007 C:\WINDOWS\system32\USER32.dll

         7ff7fc90000 490062ac Oct 23 06:40:28 2008 C:\WINDOWS\system32\GDI32.dll

         7ff7c680000 45d6ccab Feb 17 03:36:43 2007 C:\WINDOWS\system32\USERENV.dll

         7ff7c450000 45d6cc90 Feb 17 03:36:16 2007 C:\WINDOWS\system32\SCESRV.dll

         7ff7e490000 45d6cc04 Feb 17 03:33:56 2007 C:\WINDOWS\system32\AUTHZ.dll

         7ff77370000 4fedd464 Jun 29 11:14:28 2012 C:\WINDOWS\system32\NETAPI32.dll

         7ff7c410000 45d6cca5 Feb 17 03:36:37 2007 C:\WINDOWS\system32\umpnpmgr.dll

         7ff7d4d0000 45d6ccb8 Feb 17 03:36:56 2007 C:\WINDOWS\system32\WINSTA.dll

         7ff65470000 45d6cc5c Feb 17 03:35:24 2007 E:\Program Files\ThirdPartyDirectory\ThirdParty2.dll

              400000 424360e9 Mar 24 19:52:57 2005 C:\WINDOWS\system32\msvcp60.dll

         7ff7d500000 45d6cc3b Feb 17 03:34:51 2007 C:\WINDOWS\system32\IMM32.DLL

              e50000 4df9462e Jun 15 18:54:22 2011 E:\Program Files\ThirdPartyDirectory\ThirdPartyServiceMonitor.dll

     

    Using the base address of ThirdPartyServiceMonitor, I dumped the header to find the Import Address Table Directory.

     

    0:000> !dh 00000000`00e50000

     

    1E000 [     758] address [size] of Import Address Table Directory

     

    Using the dps command I dumped all of the functions in the import table of ThirdPartyServiceMonitor.dll. I found msvcr80!wcscpy_s in the function list. This indicates ThirdPartyServiceMonitor.dll makes calls to the msvcr80!wcscpy_s.

     

    0:000> dps 00000000`00e50000+ 1E000 l758/@$ptrsize

    <snippet>

    .

    .

    00000000`00e6e458  00000000`7814d890 msvcr80!_wcsnicmp

    00000000`00e6e460  00000000`7814db20 msvcr80!_wcsicmp

    00000000`00e6e498  00000000`7814ded0 msvcr80!wcscpy_s

    .

    .

     

    Since this was the only third party DLL with msvcr80!wcscpy_s in its import table, I was able to continue piecing together my stack. ThirdPartyServiceMonitor.dll was calling msvcr80!wcscpy_s and causing Services.exe to crash. At this point in the investigation, the stack looks like this-

     

    msvcr80!wcscpy_s

    ThirdPartyServiceMonitor+<offset>

     

    In my quest to continue building my “conceptual” stack without a crash dump file, I reviewed the status code from the “System Shutdown” dialog displayed when Services.exe terminated. Notice the status code -1073741811 in the error. What the heck does that mean?

     

     

    Well I easily resolved the cryptic status code by passing 0n-1073741811 to the !error command in the debugger. The “0n” prefix indicates the value should be interpreted as decimal rather than hex by the debugger. I also included the negative symbol “-“ because this also appears in status code.

     

    0:030> !error 0n-1073741811

    Error code: (NTSTATUS) 0xc000000d (3221225485) - An invalid parameter was passed to a service or function.

     

    Armed with the status code information, I reviewed the msvcr80!wcscpy_s assembly code to determine if this status code was returned at any point. In the assembly I found a call to a function named msvcr80!_invalid_parameter. In context of the message, “an invalid parameter was passed to a service or function”, this certainly sounds like the code path taken.

     

    0:000> uf msvcr80!wcscpy_s

    <snippet>

    msvcr80!wcscpy_s+0x1a

       18 00000000`7814deea e88184feff      call    msvcr80!_errno(00000000`78136370)

       18 00000000`7814deef 4533c9          xor     r9d,r9d

       18 00000000`7814def2 4533c0          xor     r8d,r8d

       18 00000000`7814def5 33d2            xor     edx,edx

       18 00000000`7814def7 33c9            xor     ecx,ecx

       18 00000000`7814def9 48c744242000000000 mov   qword ptr [rsp+20h],0

       18 00000000`7814df02 c70016000000    mov     dword ptr[rax],16h

       18 00000000`7814df08 e873d1feff      call    msvcr80!_invalid_parameter (00000000`7813b080)

       18 00000000`7814df0d b816000000      mov     eax,16h

       34 00000000`7814df12 4883c438        add     rsp,38h

       34 00000000`7814df16 c3              ret

     

    It was reasonable to add this call to my conceptual stack because the call tree makes sense.

     

    msvcr80!_invalid_parameter

    msvcr80!wcscpy_s

    ThirdPartyServiceMonitor+<offset>

     

    Because I’m a curious kind of guy, I unassembled msvcr80!_invalid_parameter to peel back another layer of the onion. To my surprise I found a call to msvcr80!_imp_TerminateProcess. BOOM! This explains why the debugger wasn’t catching the process crash. The process was terminating ‘organically’ through a TerminateProcess call rather than crashing due to an exception, however it was unexpectedly terminating. In other words, all of the services running on the machine were not expecting Services.exe to terminate.

     

    msvcr80!_invalid_parameter+0xd5

    <snippet>

       88 00000000`7813b155 ff156d200900    call    qword ptr [msvcr80!_imp_GetCurrentProcess (00000000`781cd1c8)]

       88 00000000`7813b15b ba0d0000c0      mov     edx,0C000000Dh

       88 00000000`7813b160 488bc8          mov     rcx,rax

       88 00000000`7813b163 ff1557200900    call    qword ptr [msvcr80!_imp_TerminateProcess(00000000`781cd1c0)]

     

    Now I was able to cobble together a fairly accurate stack without a dump file. At this point I could tell ThirdPartyServiceMonitor.dll was passing bad parameters to msvcr80!wcscpy_s. However, this didn’t explain how FriendlyService (mentioned in the blog introduction) was triggering the issue. I needed to go deeper with a live debug by leveraging the stack information I devised.

     

    msvcr80!_imp_TerminateProcess

    msvcr80!_invalid_parameter

    msvcr80!wcscpy_s

    ThirdPartyServiceMonitor+<offset>

     

    On the customer’s server I attached Windbg to the Services.exe process and set a breakpoint on msvcr80!_invalid_parameter.

     

    0:001> bp msvcr80!_invalid_parameter

     

    Then I had the customer reproduce the issue by changing the startup type on FriendlyService in the Services MMC. As I mentioned above, this was one way to trigger the issue. BOOM! My breakpoint hit and looked exactly like the conceptual stack I pieced together. Now I was able to determine what ThirdPartyServiceMonitor was passing to msvcr80!wcscpy_s while broken in with the debugger.

     

    0:035> k

    Child-SP          RetAddr           Call Site

    00000000`105deb00 00000000`7814df67 msvcr80!_invalid_parameter+0xe3

    00000000`105df0c0 00000000`00e53045 msvcr80!wcscpy_s+0x97

    00000000`105df100 00000000`00e5947e ThirdPartyServiceMonitor+0x3045

    00000000`105df130 00000000`00e58405 ThirdPartyServiceMonitor+0x947e

    00000000`105df180 000007ff`7fd69c75 ThirdPartyServiceMonitor+0x8405

    00000000`105df1b0 000007ff`7fe9ccc9 rpcrt4!Invoke+0x65

    00000000`105df200 000007ff`7fe9d58d rpcrt4!NdrStubCall2+0x54d

     

    I reviewed the assembly of ThirdPartyServiceMonitor at the point in which it calls msvcr80!wcscpy_s. I discovered that the vendor hardcoded the size of the destination string buffer with 200 hex (512 decimal) while the size of the source string buffer was greater than 512 decimal.

     

    0:035> ub 00000000`00e53045

    ThirdPartyServiceMonitor+0x3020:

    00000000`00e53020 898324040000    mov     dword ptr [rbx+424h],eax

    00000000`00e53026 488b4738        mov     rax,qword ptr [rdi+38h]

    00000000`00e5302a 4c8b4010        mov     r8,qword ptr [rax+10h] <<<< Source Buffer

    00000000`00e5302e 4d85c0          test    r8,r8

    00000000`00e53031 7412            je      ThirdPartyServiceMonitor+0x3045 (00000000`00e53045)

    00000000`00e53033 488d8b28040000  lea     rcx,[rbx+428h] <<<< Destination Buffer

    00000000`00e5303a ba00020000      mov     edx,200h <<<<< Buffer Size hardcoded to 200 hex

    00000000`00e5303f ff1553b40100    call    qword ptr [ThirdPartyServiceMonitor!PlugControl+0xff38 (00000000`00e6e498)] <<<< call to msvcr80!wcscpy_s

    00000000`00e53045 eb16            jmp     ThirdPartyServiceMonitor +0x305d (00000000`00e5305d) <<<< return from msvcr80!wcscpy_s

     

    0:035> .formats 200

    Evaluate expression:

      Hex:     00000000`00000200

      Decimal: 512

     

    Here is the definition of wcscpy_s from MSDN

    errno_t wcscpy_s(

       wchar_t *strDestination,         // Location of destination string buffer

       size_t numberOfElements,         // Size of the destination string buffer.

       const wchar_t *strSource         // Null-terminated source string buffer.

    );

     

    Here are the parameters passed to msvcr80!wcscpy_s. As a reminder, the x64 compiler uses rcx to pass the first parameter, rdx for the second, and r8 for the third. In this case the buffer size was the second parameter in rdx and the source buffer was in r8, the third parameter.

     

    0:035> dq 00000000`00e6e498 l1

    00000000`00e6e498  00000000`7814ded0

     

    0:035> ln 00000000`7814ded0

    (00000000`7814ded0)   msvcr80!wcscpy_s   |  (00000000`7814df80)   msvcr80!wcsncpy_s

    Exact matches:

        msvcr80!wcscpy_s

     

    Dumping the source string in r8 showed the string was clearly longer than 512 characters.

     

    0:035> dc 00000000`0103b438

    00000000`0103b438  003a0000 0049005c 0074006e 00670065  ..:.\.F.r.e.i.n.

    00000000`0103b448  00610072 00690074 006e006f 00670041  d.l.y.S.e.r.v.i.

    00000000`0103b458  006e0065 005c0074 0069006c 005c0062  c.e.\.l.i.b.\..

    .

    .

    0:035> dc

    00000000`0103b738  00650070 002e0072 00700061 002e0070  p.e.r...a.p.p...

    00000000`0103b748  00610070 00610072 0065006d 00650074  p.a.r.a.m.e.t.e.

    00000000`0103b758  002e0072 003d0031 00770020 00610072  r...1.=. .w.r.a.

    00000000`0103b768  00700070 00720065 0061002e 00700070  p.p.e.r...a.p.p.

    00000000`0103b778  0070002e 00720061 006d0061 00740065  ..p.a.r.a.m.e.t.

    00000000`0103b788  00720065 0032002e 0020003d 00720077  e.r...2.=. .w.r.

    00000000`0103b798  00700061 00650070 002e0072 00700061  a.p.p.e.r...a.p.

    00000000`0103b7a8  002e0070 00610070 00610072 0065006d  p...p.a.r.a.m.e.

    0:035> dc

    00000000`0103b7b8  00650074 002e0072 003d0033 00770020  t.e.r...3.=. .w.

    00000000`0103b7c8  00610072 00700070 00720065 0061002e  r.a.p.p.e.r...a.

    00000000`0103b7d8  00700070 0070002e 00720061 006d0061  p.p...p.a.r.a.m.

    00000000`0103b7e8  00740065 00720065 0034002e 0020003d  e.t.e.r...4.=. .

    00000000`0103b7f8  00720077 00700061 00650070 002e0072  w.r.a.p.p.e.r...

    00000000`0103b808  00700061 002e0070 00610070 00610072  a.p.p...p.a.r.a.

    00000000`0103b818  0065006d 00650074 002e0072 003d0035  m.e.t.e.r...5.=.

    00000000`0103b828  00770020 00610072 00700070 00720065  .w.r.a.p.p.e.r.

     

    It was not hard to figure out this string was the imagefile path located at HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\FriendlyService. You can see from the string that service takes parameters which increased the size of the image path beyond 512 characters.

     

    FriendlyService\lib\friendly.3\sbin\friendlywindows-x86-32.exe-s E:\ FriendlyService\conf\wrapper.conf set.DATA_APP=apia "set.DATA_APP_LONG= FriendlyServiceVendor" set.DATA_EXE=E:\ FriendlyService\bin\..\lib\friendly.3\bin set.DATA_HOME=E:\ FriendlyService\bin\..\lib\friendly.3 set.INSTALL_DIR=E:\ FriendlyService\bin\.. wrapper.working.dir=E:\ FriendlyService\bin\.. wrapper.app.parameter.1= wrapper.app.parameter.2= wrapper.app.parameter.3= wrapper.app.parameter.4= wrapper.app.parameter.5= wrapper.app.parameter.6= wrapper.app.parameter.7= wrapper.app.parameter.8= wrapper.app.parameter.9=

     

    The ThirdPartyServiceMonitor hooks any changes made to a service (e.g. changing the Startup Type, changing the dependencies, stopping the service etc...). After hooking the change, ThirdPartyServiceMonitor.dll performs a string copy of the service’s image file path. In most cases this works like a champ, however in this instance, the FriendlyService image path from vendor 1 is really long and the ThirdPartyServiceMonitor from vendor 2 doesn’t account for service image paths exceeding 512 characters. This is the perfect storm! ThirdPartyServiceMonitor needs to remove the hardcoded buffer size.

     

    This example occurred on Windows Server 2003.  Starting in Windows 7 and Windows Server 2008 R2, Windows has added functionality for catching processes that exit ‘organically’ through a TerminateProcess call.  You can find information on this added functionality on MSDN.

  • Ntdebugging Blog

    Debugging a Crash, Found a Trojan

    • 8 Comments

    Hi, I'm Manish from Global Escalation Services. I would like to present a multiple random bug check issue, which was caused by malicious code (trojan) running on the machine. This is the walkthrough of how we found the virus on the server.


    In this particular dump, the machine crashed with Bugcheck 0xA (IRQL_NOT_LESS_OR_EQUAL) because we got a Page Fault at dispatch level, also known as DPC Level (IRQL 2). Windows system architecture governs that we cannot have a page fault at dispatch level because paging requires I/O, I/O requires a wait, and we cannot wait while the IRQL is above dispatch level.  So when this anomaly happens Windows will intentionally crash the machine.

    We trapped in CcMapData because we touched the address c226d800 which was not valid because it’s paged out. If we look at implementation of CcMapData on MSDN http://msdn.microsoft.com/en-us/library/windows/hardware/ff539155(v=vs.85).aspx we see that this function can only be called below Dispatch Level, but the current CPU IRQL is 2.


    So how did this happen?  The most likely possibility is that some driver on the stack raised the IRQL by calling KeRaiseIrql and then forgot to lower it by calling KeLowerIrql.  There are many drivers on this stack and anyone could be the culprit. It is difficult to track when one of these may have done it as it’s long gone.


    We could have enabled IRQL Checking using Driver Verifier to find the culprit but we have to enable it on all drivers listed in the stack (and possibly others), which could cause some performance issues.  Also this was not the only crash we were seeing; there were various stop codes.

    So before going the verifier route I decided to dig more into this dump. I noticed there is an address on the stack for which the module name is not getting resolved. This looked odd (suspicious) as most of the time the debugger does a great job of finding the module.

    I started investigating what is this module.  It turned out to be a Trojan “TrojanDropper:Win32/Sirefef.B”.
    http://www.microsoft.com/security/portal/Threat/Encyclopedia/Entry.aspx?Name=TrojanDropper%3AWin32%2FSirefef.B

     

    0: kd> !analyze -v

    *******************************************************************************

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

    *******************************************************************************

    IRQL_NOT_LESS_OR_EQUAL (a)

    An attempt was made to access a pageable (or completely invalid) address at an

    interrupt request level (IRQL) that is too high.  This is usually

    caused by drivers using improper addresses.

    If a kernel debugger is available get the stack backtrace.

    Arguments:

    Arg1: c226d800, memory referenced

    Arg2: d0000002, IRQL

    Arg3: 00000000, bitfield :

          bit 0 : value 0 = read operation, 1 = write operation

          bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)

    Arg4: 808b64a6, address which referenced memory

     

    0: kd> kv

    ChildEBP RetAddr  Args to Child             

    f78ae41c 808b64a6 badb0d00 00000000 00000001 nt!KiTrap0E+0x2a7 (FPO: [0,0] TrapFrame @ f78ae41c)

    f78ae4cc f71a6f2d 8b22d520 f78ae4fc 00000400 nt!CcMapData+0x8c (FPO: [Non-Fpo])

    f78ae4ec f71a4494 f78ae7ec 8b64c150 01c6d800 Ntfs!NtfsMapStream+0x4b (FPO: [Non-Fpo])

    f78ae560 f71a6df0 f78ae7ec 8b3a7100 e7c50ce0 Ntfs!NtfsReadMftRecord+0x86 (FPO: [Non-Fpo])

    f78ae598 f71a6fac f78ae7ec 8b3a7100 e7c50ce0 Ntfs!NtfsReadFileRecord+0x7a (FPO: [Non-Fpo])

    f78ae5d0 f718e46d f78ae7ec e7c50cd8 e7c50ce0 Ntfs!NtfsLookupInFileRecord+0x37 (FPO: [Non-Fpo])

    f78ae67c f718e541 f78ae7ec e7c50cd8 f718e2cb Ntfs!NtfsWalkUpTree+0xbe (FPO: [Non-Fpo])

    f78ae6d8 f718e263 f78ae7ec e7c50cd8 00000000 Ntfs!NtfsBuildNormalizedName+0x44 (FPO: [Non-Fpo])

    f78ae704 f7196c2e f78ae7ec 8801d600 e7c50da0 Ntfs!NtfsQueryNameInfo+0x4b (FPO: [Non-Fpo])

    f78ae774 f71a0ff6 f78ae7ec 88081cb0 8b5f9260 Ntfs!NtfsCommonQueryInformation+0x291 (FPO: [Non-Fpo])

    f78ae7d8 f71a102f f78ae7ec 88081cb0 00000001 Ntfs!NtfsFsdDispatchSwitch+0x12a (FPO: [Non-Fpo])

    f78ae8f4 8081df85 8b3a7020 88081cb0 88081cb0 Ntfs!NtfsFsdDispatchWait+0x1c (FPO: [Non-Fpo])

    f78ae908 f721fd28 8b2fd220 8b60d308 8b54b020 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78ae934 8081df85 8b5f9260 88081cb0 88081cb0 fltMgr!FltpDispatch+0x152 (FPO: [Non-Fpo])

    f78ae948 f721fd28 88081ed0 8b60d308 c000000d nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78ae974 8081df85 8b54b020 88081cb0 88081cb0 fltMgr!FltpDispatch+0x152 (FPO: [Non-Fpo])

    f78ae988 f5c62bec 88081cb0 8b54a980 88081cb0 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    WARNING: Stack unwind information not available. Following frames may be wrong.

    f78ae99c f5c5e3ee 8b03b690 00000000 f78ae9c0 CtxSbx+0x5bec

    f78ae9ac 8081df85 8b03b690 88081cb0 8b0528e0 CtxSbx+0x13ee

    f78ae9c0 f61074e1 8b0528e0 8801d600 f78aea00nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78ae9e4 f61075d0 8b0a9b80 00081cb0 f78aea08 CtxAltStr+0x44e1

    f78ae9f4 8081df85 8b0a9b80 88081cb0 88081ed0 CtxAltStr+0x45d0

    f78aea08 8b5cfc89 00000000 87ef0000 87ef9002 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aec90 8081df85 8b5ef610 8b08c110 8b08c2a8 0x8b5cfc89 <------------ This looks odd what is this module?

    f78aeca4 f7241607 8b08c2a8 00000000 f78aece8nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aecb4 f72412b2 8b08c2a8 8b392b70 87f11974 CLASSPNP!SubmitTransferPacket+0xbb (FPO: [Non-Fpo])

    f78aece8 f7241533 00000000 00000e00 87f11808 CLASSPNP!ServiceTransferRequest+0x1e4 (FPO: [Non-Fpo])

    f78aed0c 8081df85 8b392ab8 00000000 8b2a2670 CLASSPNP!ClassReadWrite+0x159 (FPO: [Non-Fpo])

    f78aed20 f74c80cf 8b2b7d80 87f11998 f78aed44 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aed30 8081df85 8b6e4020 87f11808 87f119bc PartMgr!PmReadWrite+0x95 (FPO: [Non-Fpo])

    f78aed44 f7317053 87f119d8 8b6e8148 882b9888 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aed60 8081df85 8b2b7cc8 87f11808 87f119fc ftdisk!FtDiskReadWrite+0x1a9 (FPO: [Non-Fpo])

    f78aed74 f72cf4f5 885360cc 88536098 87f26810 nt!IofCallDriver+0x45 (FPO: [Non-Fpo])

    f78aed90 f72d1517 87f11808 885360cc 8b60c470 volsnap!VspDecrementIrpRefCount+0x14f (FPO: [Non-Fpo])

    f78aeda8 f72c0398 87f26810 87f26810 88536098 volsnap!VspWriteVolumePhase22+0x3d (FPO: [Non-Fpo])

    f78aee30 f72d15d3 00f26810 885360cc 00000000 volsnap!VspAcquireNonPagedResource+0xc6 (FPO: [Non-Fpo])

    f78aee50 8081e123 00000000 87f215e8 88536098 volsnap!VspWriteVolumePhase2+0x59 (FPO: [Non-Fpo])

    f78aee80 f7241829 f78aeeb0 f72413ec 8b392ab8 nt!IopfCompleteRequest+0xcd (FPO: [Non-Fpo])

    f78aee88 f72413ec 8b392ab8 87f215e8 00000001 CLASSPNP!ClassCompleteRequest+0x11 (FPO: [Non-Fpo])

    f78aeeb0 8081e123 00000000 8b08c428 8b08c5c0 CLASSPNP!TransferPktComplete+0x1fd (FPO: [Non-Fpo])

    f78aeee0 f7266545 8b6e30e8 8b08c428 f78aef24 nt!IopfCompleteRequest+0xcd (FPO: [Non-Fpo])

    f78aeef0 f7265a8a 87f856a8 00000001 00000000 SCSIPORT!SpCompleteRequest+0x5e (FPO: [Non-Fpo])

    f78aef24 f7265130 8b6e30e8 87f856a8 f78aef9b SCSIPORT!SpProcessCompletedRequest+0x6a7 (FPO: [Non-Fpo])

    f78aef9c 8083211c 8b6e30a4 8b6e3030 00000000 SCSIPORT!ScsiPortCompletionDpc+0x2bd (FPO: [Non-Fpo])

    f78aeff4 8088dba7 f3f4f92c 00000000 00000000 nt!KiRetireDpcList+0xca (FPO: [Non-Fpo])

    f3f4f948 80a603d9 ffdffa02 f3f4f980 f3f4f980 nt!KiDispatchInterrupt+0x37 (FPO: [Uses EBP] [0,0,1])

    f3f4f964 80a60577 8b6c226c f3f4f980 8088d91d hal!HalpCheckForSoftwareInterrupt+0x81 (FPO: [Non-Fpo])

    f3f4f970 8088d91d 8b304c00 000001a3 f3f4fa04 hal!HalEndSystemInterrupt+0x67 (FPO: [Non-Fpo])

    f3f4f970 809395e7 8b304c00 000001a3 f3f4fa04 nt!KiInterruptDispatch+0x5d (FPO: [0,2] TrapFrame @ f3f4f980)

    f3f4fa04 80939c37 88139178 88028301 00000008 nt!ObpAllocateObject+0x199 (FPO: [Non-Fpo])

    f3f4fa38 808f8d28 00000000 8b76aad0 f3f4fa70 nt!ObCreateObject+0x129 (FPO: [Non-Fpo])

    f3f4fb44 80937a40 8b6afd10 00000000 88028398 nt!IopParseDevice+0x710 (FPO: [Non-Fpo])

    f3f4fbc4 80933b74 00000000 f3f4fc04 00000042 nt!ObpLookupObjectName+0x5b0 (FPO: [Non-Fpo])

    f3f4fc18 808eaee7 00000000 00000000 dffa7c01 nt!ObOpenObjectByName+0xea (FPO: [Non-Fpo])

    f3f4fc94 808ec181 077ef198 c0140000 077ef14c nt!IopCreateFile+0x447 (FPO: [Non-Fpo])

    f3f4fcf0 808eec10 077ef198 c0140000 077ef14c nt!IoCreateFile+0xa3 (FPO: [Non-Fpo])

    f3f4fd30 808897ec 077ef198 c0140000 077ef14c nt!NtCreateFile+0x30 (FPO: [Non-Fpo])

    f3f4fd30 7c82847c 077ef198 c0140000 077ef14c nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f3f4fd64)

    077ef22c 00000000 00000000 00000000 00000000 0x7c82847c

       

    The current CPU IRQL is 2, at which pagefaults cannot be serviced, hence windows crashed the machine.

    0: kd> !irql

    Debugger saved IRQL for processor 0x0 -- 2 (DISPATCH_LEVEL)

     

    Un-assembling from the return address of this unknown driver, to try to confirm that this is really driver code and that it really does belong in this call stack:

    0: kd> ub 8b5cfc89

    8b5cfc62 8bd7            mov     edx,edi

    8b5cfc64 c60605          mov     byte ptr [esi],5

    8b5cfc67 895e18          mov     dword ptr [esi+18h],ebx

    8b5cfc6a c7460400020000  mov     dword ptr [esi+4],200h

    8b5cfc71 c7460809000000  mov     dword ptr [esi+8],9

    8b5cfc78 c7461c70fb5c8b  mov     dword ptr [esi+1Ch],8B5CFB70h

    8b5cfc7f c64603e0        mov     byte ptr [esi+3],0E0h

    8b5cfc83 ff158c805d8b    call    dword ptr ds:[8B5D808Ch]


    Sure does call IofCallDriver

    0: kd> dps 8B5D808Ch l1

    8b5d808c  8081df40 nt!IofCallDriver

     

    So what is this driver? In Windows every image starts with a PE header which starts with letters “MZ”. So I started looking for PE header. I took the offset of the module on the stack and went back to its page boundary, then I started moving 1 page back at a time looking for the PE header.

    0: kd> dc 8b5cf000

    8b5cf000  0010b9f2 f02b0000 3b063c8b 83137538  ......+..<.;8u..

    8b5cf010  c08304e9 04f98304 b85fee73 00000001  ........s._.....

    8b5cf020  9cb8c35e b98b5d86 00000010 ff8bd02b  ^....]......+...

    8b5cf030  3b02348b 83137530 c08304e9 04f98304  .4.;0u..........

    8b5cf040  b85fee73 00000001 335fc35e ccc35ec0  s._.....^._3.^..

    8b5cf050  83ec8b55 78a04cec 538b5da4 c0b60f56  U....L.x.].SV...

    8b5cf060  827ae857 ff330000 33f46589 f845c7db  W.z...3..e.3..E.

    8b5cf070  00000400 8b084d8b 52510c55 50b4458d  .....M..U.QR.E.P

     

    0: kd> dc 8b5cf000-1000

    8b5ce000  01c73024 00000000 c70cc483 00800002  $0..............

    8b5ce010  845e5f00 b10874db 0815ff01 8b8b5d80  ._^..t.......]..

    8b5ce020  6a0c2444 15ff5000 8b5d8028 14c25b5d  D$.j.P..(.].][..

    8b5ce030  cccccc00 cccccccc cccccccc cccccccc  ................

    8b5ce040  6a306a56 2415ff00 8b8b5d80 74f685f0  Vj0j...$.].....t

    8b5ce050  6a006a53 68026a01 8b5d0892 5d08ae68  Sj.j.j.h..].h..]

    8b5ce060  ff006a8b 5d80ac15 ff56508b 5d80a815  .j.....].PV....]

    8b5ce070  000d8b8b ff8b5da2 5d80b015 6a006a8b  .....].....].j.j


    0: kd> dc 8b5cf000-1000*2

    8b5cd000  0689c033 89044689 46890846 1046890c  3....F..F..F..F.

    8b5cd010  89144689 ec831846 1c46891c 57204689  .F..F.....F..F W

    8b5cd020  85244689 8d0574f6 02eb284e c033c933  .F$..t..N(..3.3.

    8b5cd030  41890189 08418904 8b34468b 4e891048  ...A..A..F4.H..N

    8b5cd040  14508b10 8b145689 4e891848 1c508b18  ..P..V..H..N..P.

    8b5cd050  8b1c5689 4e891848 1c508b20 2424448d  .V..H..N .P..D$$

    8b5cd060  244c8d50 186a510c 8b245689 6a302454  P.L$.Qj..V$.T$0j

    8b5cd070  46c65205 46c70005 00000008 0c46c700  .R.F...F......F.

     

    Finally I found the PE header for this image.

    0: kd> dc 8b5cf000-1000*3

    8b5cc000  00905a4d 00000003 00000004 0000ffff  MZ..............

    8b5cc010  000000b8 00000000 00000040 00000000  ........@.......

    8b5cc020  00000000 00000000 00000000 00000000  ................

    8b5cc030  00000000 00000000 00000000 000000d0  ................

    8b5cc040  0eba1f0e cd09b400 4c01b821 685421cd  ........!..L.!Th

    8b5cc050  70207369 72676f72 63206d61 6f6e6e61  is program canno

    8b5cc060  65622074 6e757220 206e6920 20534f44  t be run in DOS

    8b5cc070  65646f6d 0a0d0d2e 00000024 00000000  mode....$.......

     

    Using the built-in debugger extension !dh I dumped the header of this image to find the name.  Unfortunately there is no name for this image. This address 8b5cc000 is not in the loaded module list, which raised further suspicion. Either it is hiding its load address or this driver was not loaded by standard loading mechanism. This module date shows it’s pretty recent build.

    0: kd> !dh 8b5cc000

     

    File Type: DLL

    FILE HEADER VALUES

         14C machine (i386)

           4 number of sections

    4EA3461E time date stamp Sun Oct 23 04:09:26 2011

     

           0 file pointer to symbol table

           0 number of symbols

          E0 size of optional header

        2102 characteristics

                Executable

                32 bit word machine

                DLL

     

    OPTIONAL HEADER VALUES

         10B magic #

        9.00 linker version

        A400 size of code

        2000 size of initialized data

           0 size of uninitialized data

        46C0 address of entry point

        1000 base of code

             ----- new -----

    10000000 image base

        1000 section alignment

         200 file alignment

           1 subsystem (Native)

        5.00 operating system version

        0.00 image version

        5.00 subsystem version

       10000 size of image

         400 size of headers

        DF1F checksum

    00100000 size of stack reserve

    00001000 size of stack commit

    00100000 size of heap reserve

    00001000 size of heap commit

           0  DLL characteristics

           0 [       0] address [size] of Export Directory

        C91C [      3C] address [size] of Import Directory

           0 [       0] address [size] of Resource Directory

           0 [       0] address [size] of Exception Directory

           0 [       0] address [size] of Security Directory

        F000 [     3FC] address [size] of Base Relocation Directory

           0 [       0] address [size] of Debug Directory

           0 [       0] address [size] of Description Directory

           0 [       0] address [size] of Special Directory

           0 [       0] address [size] of Thread Storage Directory

           0 [       0] address [size] of Load Configuration Directory

           0 [       0] address [size] of Bound Import Directory

        C000 [     1A8] address [size] of Import Address Table Directory

           0 [       0] address [size] of Delay Import Directory

           0 [       0] address [size] of COR20 Header Directory

           0 [       0] address [size] of Reserved Directory

     

     

    SECTION HEADER #1

       .text name

        A354 virtual size

        1000 virtual address

        A400 size of raw data

         400 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    60000020 flags

             Code

             (no align specified)

             Execute Read

     

    SECTION HEADER #2

      .rdata name

        13AC virtual size

        C000 virtual address

        1400 size of raw data

        A800 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    40000040 flags

             Initialized Data

             (no align specified)

             Read Only

     

    SECTION HEADER #3

       .data name

         4B0 virtual size

        E000 virtual address

         200 size of raw data

        BC00 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    C0000040 flags

             Initialized Data

             (no align specified)

             Read Write

     

    SECTION HEADER #4

      .reloc name

         576 virtual size

        F000 virtual address

         600 size of raw data

        BE00 file pointer to raw data

           0 file pointer to relocation table

           0 file pointer to line numbers

           0 number of relocations

           0 number of line numbers

    42000040 flags

             Initialized Data

             Discardable

             (no align specified)

             Read Only


    0: kd> !lmi 8b5cc000 

    Loaded Module Info: [8b5cc000]

    ffffffff8b5cc000 is not a valid address

     

    0: kd> lmvm 8b5cc000 

    start    end        module name


    Checking the import table it does have calls to raise and lower the IRQL. We get to the import table by taking the base address plus the offset to the Import Address Table Directory.  The below output is just a snippet of the whole table.

    0: kd> dps 8b5cc000+c000

    8b5d8000  80a603f4 hal!KfLowerIrql

    8b5d8004  80a5ff00 hal!KeGetCurrentIrql

    8b5d8008  80a600b4 hal!KfRaiseIrql

     

    Dumping the entire image contents in memory to find more clues about this driver.  Again, I am only showing snippets of the whole output.

    0: kd> dc 8b5cc000  L?10000/4

    8b5cc000  00905a4d 00000003 00000004 0000ffff  MZ..............

    8b5cc010  000000b8 00000000 00000040 00000000  ........@.......

    8b5cc020  00000000 00000000 00000000 00000000  ................

    8b5cc030  00000000 00000000 00000000 000000d0  ................

    8b5cc040  0eba1f0e cd09b400 4c01b821 685421cd  ........!..L.!Th

    8b5cc050  70207369 72676f72 63206d61 6f6e6e61  is program canno

    8b5cc060  65622074 6e757220 206e6920 20534f44  t be run in DOS

    8b5cc070  65646f6d 0a0d0d2e 00000024 00000000  mode....$.......

    8b5d5e20  76000000 66697265 77252079 00000a5a  ...verify %wZ...

    8b5d5e30  31000000 35343332 39383736 33323130  ...1234567890123

    8b5d5e40  37363534 31303938 35343332 39383736  4567890123456789

    8b5d5e50  33323130 37363534 31303938 35343332  0123456789012345

    8b5d5e60  39383736 33323130 37363534 31303938  6789012345678901

    8b5d5e70  00343332 66000000 646e756f 67697320  234....found sig

    8b5d5e80  7574616e 3d206572 0a752520 b4000000  nature = %u.....   

     

    Interestingly this image has other images (modules) embedded in it.  We can see other PE headers, which again have no name.  This looks highly suspicious and resembles behavior used by malicious software.

    8b5d0970  f775c085 4848c78b 4dc35f5e 0300905a  ..u...HH^_.MZ...

    8b5d0980  04000000 ff000000 b80000ff 00000000  ................

    8b5d0990  40000000 00000000 00000000 00000000  ...@............

    8b5d09a0  00000000 00000000 00000000 00000000  ................

    8b5d09b0  00000000 c8000000 0e000000 000eba1f  ................

    8b5d09c0  21cd09b4 cd4c01b8 69685421 72702073  ...!..L.!This pr

    8b5d09d0  6172676f 6163206d 746f6e6e 20656220  ogram cannot be

    8b5d09e0  206e7572 44206e69 6d20534f 2e65646f  run in DOS mode.

    8b5d2200  4d00004e 0300905a 04000000 ff000000  N..MZ...........

    8b5d2210  b80000ff 00000000 40000000 00000000  ...........@....

    8b5d2220  00000000 00000000 00000000 00000000  ................

    8b5d2230  00000000 00000000 00000000 f0000000  ................

    8b5d2240  0e000000 000eba1f 21cd09b4 cd4c01b8  ...........!..L.

    8b5d2250  69685421 72702073 6172676f 6163206d  !This program ca

    8b5d2260  746f6e6e 20656220 206e7572 44206e69  nnot be run in D

    8b5d2270  6d20534f 2e65646f 240a0d0d 00000000  OS mode....$....

     

    After ensuring my AV definitions were up to date, I decided to dump this memory contents into a file onto my machine. The moment contents were written my AV Microsoft Forefront Endpoint Protection caught a Trojan in this file.

    0: kd> .writemem c:\temp\drv.sys 8b5cc000   L?10000
    Writing 10000 bytes................................

       
    image001

     

    image003


    Before any further trouble shooting we asked the customer to clean the Trojan. Once we did that bug checks disappeared.


    Hope you enjoyed reading this post.
  • Ntdebugging Blog

    Understanding Pool Corruption Part 1 – Buffer Overflows

    • 8 Comments

    Before we can discuss pool corruption we must understand what pool is.  Pool is kernel mode memory used as a storage space for drivers.  Pool is organized in a similar way to how you might use a notepad when taking notes from a lecture or a book.  Some notes may be 1 line, others may be many lines.  Many different notes are on the same page.

     

    Memory is also organized into pages, typically a page of memory is 4KB.  The Windows memory manager breaks up this 4KB page into smaller blocks.  One block may be as small as 8 bytes or possibly much larger.  Each of these blocks exists side by side with other blocks.

     

    The !pool command can be used to see the pool blocks stored in a page.

     

    kd> !pool fffffa8003f42000

    Pool page fffffa8003f42000 region is Nonpaged pool

    *fffffa8003f42000 size:  410 previous size:    0  (Free)      *Irp

                Pooltag Irp  : Io, IRP packets

    fffffa8003f42410 size:   40 previous size:  410  (Allocated)  MmSe

    fffffa8003f42450 size:  150 previous size:   40  (Allocated)  File

    fffffa8003f425a0 size:   80 previous size:  150  (Allocated)  Even

    fffffa8003f42620 size:   c0 previous size:   80  (Allocated)  EtwR

    fffffa8003f426e0 size:   d0 previous size:   c0  (Allocated)  CcBc

    fffffa8003f427b0 size:   d0 previous size:   d0  (Allocated)  CcBc

    fffffa8003f42880 size:   20 previous size:   d0  (Free)       Free

    fffffa8003f428a0 size:   d0 previous size:   20  (Allocated)  Wait

    fffffa8003f42970 size:   80 previous size:   d0  (Allocated)  CM44

    fffffa8003f429f0 size:   80 previous size:   80  (Allocated)  Even

    fffffa8003f42a70 size:   80 previous size:   80  (Allocated)  Even

    fffffa8003f42af0 size:   d0 previous size:   80  (Allocated)  Wait

    fffffa8003f42bc0 size:   80 previous size:   d0  (Allocated)  CM44

    fffffa8003f42c40 size:   d0 previous size:   80  (Allocated)  Wait

    fffffa8003f42d10 size:  230 previous size:   d0  (Allocated)  ALPC

    fffffa8003f42f40 size:   c0 previous size:  230  (Allocated)  EtwR

     

    Because many pool allocations are stored in the same page, it is critical that every driver only use the space they have allocated.  If DriverA uses more space than it allocated they will write into the next driver’s space (DriverB) and corrupt DriverB’s data.  This overwrite into the next driver’s space is called a buffer overflow.  Later either the memory manager or DriverB will attempt to use this corrupted memory and will encounter unexpected information.  This unexpected information typically results in a blue screen.

     

    The NotMyFault application from Sysinternals has an option to force a buffer overflow.  This can be used to demonstrate pool corruption.  Choosing the “Buffer overflow” option and clicking “Crash” will cause a buffer overflow in pool.  The system may not immediately blue screen after clicking the Crash button.  The system will remain stable until something attempts to use the corrupted memory.  Using the system will often eventually result in a blue screen.

     

    NotMyFault

     

    Often pool corruption appears as a stop 0x19 BAD_POOL_HEADER or stop 0xC2 BAD_POOL_CALLER.  These stop codes make it easy to determine that pool corruption is involved in the crash.  However, the results of accessing unexpected memory can vary widely, as a result pool corruption can result in many different types of bugchecks.

     

    As with any blue screen dump analysis the best place to start is with !analyze -v.  This command will display the stop code and parameters, and do some basic interpretation of the crash.

     

    kd> !analyze -v

    *******************************************************************************

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

    *******************************************************************************

     

    SYSTEM_SERVICE_EXCEPTION (3b)

    An exception happened while executing a system service routine.

    Arguments:

    Arg1: 00000000c0000005, Exception code that caused the bugcheck

    Arg2: fffff8009267244a, Address of the instruction which caused the bugcheck

    Arg3: fffff88004763560, Address of the context record for the exception that caused the bugcheck

    Arg4: 0000000000000000, zero.

     

    In my example the bugcheck was a stop 0x3B SYSTEM_SERVICE_EXCEPTION.  The first parameter of this stop code is c0000005, which is a status code for an access violation.  An access violation is an attempt to access invalid memory (this error is not related to permissions).  Status codes can be looked up in the WDK header ntstatus.h.

     

    The !analyze -v command also provides a helpful shortcut to get into the context of the failure.

     

    CONTEXT:  fffff88004763560 -- (.cxr 0xfffff88004763560;r)

     

    Running this command shows us the registers at the time of the crash.

     

    kd> .cxr 0xfffff88004763560

    rax=4f4f4f4f4f4f4f4f rbx=fffff80092690460 rcx=fffff800926fbc60

    rdx=0000000000000000 rsi=0000000000001000 rdi=0000000000000000

    rip=fffff8009267244a rsp=fffff88004763f60 rbp=fffff8009268fb40

    r8=fffffa8001a1b820  r9=0000000000000001 r10=fffff800926fbc60

    r11=0000000000000011 r12=0000000000000000 r13=fffff8009268fb48

    r14=0000000000000012 r15=000000006374504d

    iopl=0         nv up ei pl nz na po nc

    cs=0010  ss=0018  ds=002b  es=002b  fs=0053  gs=002b             efl=00010206

    nt!ExAllocatePoolWithTag+0x442:

    fffff800`9267244a 4c8b4808        mov     r9,qword ptr [rax+8] ds:002b:4f4f4f4f`4f4f4f57=????????????????

     

    From the above output we can see that the crash occurred in ExAllocatePoolWithTag, which is a good indication that the crash is due to pool corruption.  Often an engineer looking at a dump will stop at this point and conclude that a crash was caused by corruption, however we can go further.

     

    The instruction that we failed on was dereferencing rax+8.  The rax register contains 4f4f4f4f4f4f4f4f, which does not fit with the canonical form required for pointers on x64 systems.  This tells us that the system crashed because the data in rax is expected to be a pointer but it is not one.

     

    To determine why rax does not contain the expected data we must examine the instructions prior to where the failure occurred.

     

    kd> ub .

    nt!KzAcquireQueuedSpinLock [inlined in nt!ExAllocatePoolWithTag+0x421]:

    fffff800`92672429 488d542440      lea     rdx,[rsp+40h]

    fffff800`9267242e 49875500        xchg    rdx,qword ptr [r13]

    fffff800`92672432 4885d2          test    rdx,rdx

    fffff800`92672435 0f85c3030000    jne     nt!ExAllocatePoolWithTag+0x7ec (fffff800`926727fe)

    fffff800`9267243b 48391b          cmp     qword ptr [rbx],rbx

    fffff800`9267243e 0f8464060000    je      nt!ExAllocatePoolWithTag+0xa94 (fffff800`92672aa8)

    fffff800`92672444 4c8b03          mov     r8,qword ptr [rbx]

    fffff800`92672447 498b00          mov     rax,qword ptr [r8]

     

    The assembly shows that rax originated from the data pointed to by r8.  The .cxr command we ran earlier shows that r8 is fffffa8001a1b820.  If we examine the data at fffffa8001a1b820 we see that it matches the contents of rax, which confirms this memory is the source of the unexpected data in rax.

     

    kd> dq fffffa8001a1b820 l1

    fffffa80`01a1b820  4f4f4f4f`4f4f4f4f

     

    To determine if this unexpected data is caused by pool corruption we can use the !pool command.

     

    kd> !pool fffffa8001a1b820

    Pool page fffffa8001a1b820 region is Nonpaged pool

     fffffa8001a1b000 size:  810 previous size:    0  (Allocated)  None

     

    fffffa8001a1b810 doesn't look like a valid small pool allocation, checking to see

    if the entire page is actually part of a large page allocation...

     

    fffffa8001a1b810 is not a valid large pool allocation, checking large session pool...

    fffffa8001a1b810 is freed (or corrupt) pool

    Bad previous allocation size @fffffa8001a1b810, last size was 81

     

    ***

    *** An error (or corruption) in the pool was detected;

    *** Attempting to diagnose the problem.

    ***

    *** Use !poolval fffffa8001a1b000 for more details.

     

     

    Pool page [ fffffa8001a1b000 ] is __inVALID.

     

    Analyzing linked list...

    [ fffffa8001a1b000 --> fffffa8001a1b010 (size = 0x10 bytes)]: Corrupt region

     

     

    Scanning for single bit errors...

     

    None found

     

    The above output does not look like the !pool command we used earlier.   This output shows corruption to the pool header which prevented the command from walking the chain of allocations.

     

    The above output shows that there is an allocation at fffffa8001a1b000 of size 810.  If we look at this memory we should see a pool header.  Instead what we see is a pattern of 4f4f4f4f`4f4f4f4f.

     

    kd> dq fffffa8001a1b000 + 810

    fffffa80`01a1b810  4f4f4f4f`4f4f4f4f 4f4f4f4f`4f4f4f4f

    fffffa80`01a1b820  4f4f4f4f`4f4f4f4f 4f4f4f4f`4f4f4f4f

    fffffa80`01a1b830  4f4f4f4f`4f4f4f4f 00574f4c`46524556

    fffffa80`01a1b840  00000000`00000000 00000000`00000000

    fffffa80`01a1b850  00000000`00000000 00000000`00000000

    fffffa80`01a1b860  00000000`00000000 00000000`00000000

    fffffa80`01a1b870  00000000`00000000 00000000`00000000

    fffffa80`01a1b880  00000000`00000000 00000000`00000000

     

    At this point we can be confident that the system crashed because of pool corruption.

     

    Because the corruption occurred in the past, and a dump is a snapshot of the current state of the system, there is no concrete evidence to indicate how the memory came to be corrupted.  It is possible the driver that allocated the pool block immediately preceding the corruption is the one that wrote to the wrong location and caused this corruption.  This pool block is marked with the tag “None”, we can search for this tag in memory to determine which drivers use it.

     

    kd> !for_each_module s -a @#Base @#End "None"

    fffff800`92411bc2  4e 6f 6e 65 e9 45 04 26-00 90 90 90 90 90 90 90  None.E.&........

    kd> u fffff800`92411bc2-1

    nt!ExAllocatePool+0x1:

    fffff800`92411bc1 b84e6f6e65      mov     eax,656E6F4Eh

    fffff800`92411bc6 e945042600      jmp     nt!ExAllocatePoolWithTag (fffff800`92672010)

    fffff800`92411bcb 90              nop

     

    The file Pooltag.txt lists the pool tags used for pool allocations by kernel-mode components and drivers supplied with Windows, the associated file or component (if known), and the name of the component. Pooltag.txt is installed with Debugging Tools for Windows (in the triage folder) and with the Windows WDK (in \tools\other\platform\poolmon).  Pooltag.txt shows the following for this tag:

     

    None - <unknown>    - call to ExAllocatePool

     

    Unfortunately what we find is that this tag is used when a driver calls ExAllocatePool, which does not specify a tag.  This does not allow us to determine what driver allocated the block prior to the corruption.  Even if we could tie the tag back to a driver it may not be sufficient to conclude that the driver using this tag is the one that corrupted the memory.

     

    The next step should be to enable special pool and hope to catch the corruptor in the act.  We will discuss special pool in our next article.

  • Ntdebugging Blog

    This button doesn’t do anything!

    • 8 Comments

     

    Hello - Matthew here again.  Today I'll be discussing in detail hang scenario #1 that Tate first mentioned a few blogs posts ago.  From a debugging perspective, in an ideal world an application would always provide some kind of feedback when a failure occurs.  The reality is that sometimes an application just doesn't do anything in response to a user-initiated action (such as a mouse-click) that results in a failure of some kind.  When this happens, how can you determine what is going wrong?

     

    In general, Process Monitor from Sysinternals is a great tool for gathering clues about this kind of failure.  If the failure is due to a file system or registry problem, Process Explorer will catch the problematic event.  Or if you suspect that the problem is due to something failing over the network, a network trace could help.

     

    Let's assume that the techniques described above do not move us any closer to understanding the failure.  What next?  If you don't know what the app does in the background, and you don't have source code for the app, how do you proceed?  Let's answer those questions by debugging a sample application...

     

    The Nothing button

     

    Download the sample application here.

     

     

    Here's what we know:

    1. Clicking the “Button 1” button is supposed to display a useful dialog box

    2. For certain users, clicking “Button 1” results in no observable response

    3. You don't have access to the source code or debug symbols for the app

    4. No one seems to know what the “Button 1” button does behind the scenes

    5. The developer of the application hasn't been heard from in 3 years

     

    We need to understand what exactly happens when the user clicks the “Button 1” button.  Every window has a WindowProc function that receives messages upon user input.  Since a button is considered a "control", the WindowProc for the main application window will get a WM_COMMAND message indicating that the button was clicked.  To differentiate which specific control sent the message, each WM_COMMAND message has a control identifier associated with it.

     

    So we need to:

     

    a)     Find the control identifier for “Button 1”

    b)    Find the WindowProc for the main application window

    c)     Determine where WM_COMMAND messages for the “Button 1” button are handled

    d)    Figure out what is failing in that code

     

    Let’s get started...

     

     

     

    Find the control identifier for “Button 1”      

     

    Spy++ (available as part of Visual Studio) is the tool for this job.  Click Spy -> Log Messages.  Use the Finder Tool to select the main window of ntdbghang1.exe.  On the messages tab, click “Clear All” then select “WM_COMMAND”.  Click “OK” and SPY++ will start logging.  Click “Button 1” in ntdbghang1.exe and you should see one line of text appear in the output window.  For good measure, click “Button 2” also, and you should see a second line of text.  At this point, your SPY++ window should look something like this....

     

    Spy Windows Msg

     

    We can tell from this output, that the control identifier for “Button 1” is 257 (0x101), and the control identifier for “Button 2” is 258 (0x102).  We’ll need this information later.

     

     

     

    Find the WindowProc for the main application window

     

    We can find the WindowProc address by using SPY++ again.  Click Spy -> Find Window and use the Finder Tool to select the main window of ntdbghang1.exe.  Make sure “Show properties” is selected, and then click “OK”.  You will get a dialog that looks like this....

     

    Spy Window Properties

     

    Note the value of Window Proc.  This is the address of the window procedure for the main window (the exact value may differ on your system).   We know that this function is a WindowProc, which means it is of the form...

     

    LRESULT CALLBACK WindowProc(         

        HWND hwnd,

        UINT uMsg,

        WPARAM wParam,

        LPARAM lParam

    );

     

    The meaning of wParam and lParam differ depending on what uMsg is being processed.  When a WM_COMMAND message is passed, the low-word of wParam is the control identifier, which we determined to be 0x101.  The high-word of wParam is the control notification code, which in the case of a button being clicked is BN_CLICKED (literally 0).

     

    So, we specifically are interested in the case where:

               

                uMsg = WM_COMMAND (literally 0x111)

                wParam = 0x101

     

    While looking at assembly language for the WindowProc, the stack frame will look like this...

     

    ebp    =  “old ebp”

    ebp+4  =  “return address”

    ebp+8  =  hwnd

    ebp+c  =  uMsg

    ebp+10 =  wParam

    ebp+14 =  lParam

     

     

     

    Determine where WM_COMMAND messages for the “Button 1” button are handled

     

    Once you have the address of the WindowProc, we can examine the assembly code for that function using Windbg.  Launch windbg.exe and select “File -> Attach to a Process”.  Select “ntdbghang1.exe” from the list and click “OK”.  When the debugger breaks in, you can unassemble the beginning of the WindowProc by typing “u <address>”.  Based on the address on my system, that command will be “u 01002830”.  To unassemble more just type “u” again.  I’m now going to unassemble the relevant code and explain what it means along the way...

     

     

    0:001> u 01002830

    ntdbghang1+0x2830:

     

    The first 3 instructions are a function prologue, just getting everything set up.

    01002830 8bff            mov     edi,edi

    01002832 55              push    ebp

    01002833 8bec            mov     ebp,esp

     

    Here is the code that moves the value of uMsg into ecx

    01002835 8b4d0c          mov     ecx,dword ptr [ebp+0Ch]

     

    Now the app enters the assembly equivalent of a switch statement.

    We are interested in the check for uMsg = WM_COMMAND

     

    if uMsg = WM_CREATE (1) goto 01002893

    01002838 49              dec     ecx

    01002839 7458            je      ntdbghang1+0x2893 (01002893)

    if uMsg = WM_ DESTROY (2) goto 01002889

    0100283b 49              dec     ecx

    0100283c 744b            je      ntdbghang1+0x2889 (01002889)

    if uMsg = WM_CLOSE (0x10) goto 01002889

    0100283e 83e90e          sub     ecx,0Eh

    01002841 743b            je      ntdbghang1+0x287e (0100287e)

    if uMsg = WM_COMMAND (0x111) goto 01002853

    01002843 b801010000      mov     eax,101h

    01002848 2bc8            sub     ecx,eax

    0100284a 7407            je      ntdbghang1+0x2853 (01002853)

     

    From the above switch statement we see that when uMsg = WM_COMMAND, execution moves to 01002853.  So let’s go there...

     

    0:001> u 01002853

    ntdbghang1+0x2853:

     

    Move the value of wParam into edx

    01002853 8b5510          mov     edx,dword ptr [ebp+10h]

    If LOWORD(wParam) == 0x101 (control ID for button 1) goto 0100286f

    01002856 0fb7ca          movzx   ecx,dx

    01002859 2bc8            sub     ecx,eax

    0100285b 7412            je      ntdbghang1+0x286f (0100286f)

     

    From the above assembly we can see that right away we are checking for the control ID for button 1.  This is the code path we want to follow....

     

    0:001> u 0100286f

    ntdbghang1+0x286f:

     

    If HIWORD(wparam) != BN_CLICKED (0) then goto 0100289b

    Otherwise, call the function at 010027f6

    0100286f c1ea10          shr     edx,10h

    01002872 6685d2          test    dx,dx

    01002875 7524            jne     ntdbghang1+0x289b (0100289b)

    01002877 e87affffff      call    ntdbghang1+0x27f6 (010027f6)

     

    Now it is clear that when the BN_CLICKED occurs for control id 0x101, we are going to execute the function at address 010027f6. 

     

     

     

    Figure out what is failing

     

    So now we know what code is going to run every time the button is clicked (the function at 010027f6).  Let’s examine that code and figure out what may be failing.  We’ll use “uf” to unassemble the entire function, as it is rather short.  During this first pass we’ll make up names for our local variables and functions that are called, and then we’ll revisit and figure out what they are.

     

     

    0:001> uf 010027f6

    ntdbghang1+0x27f6:

     

    Function Prologue

    010027f6 8bff            mov     edi,edi

    010027f8 55              push    ebp

    010027f9 8bec            mov     ebp,esp

     

    010027fb 51              push    ecx

    010027fc 56              push    esi

     

    call func1(0x20) [func1 address at 01002dca]

    set localvar1=0x10

    010027fd 6a20            push    20h

    010027ff c745fc10000000  mov     dword ptr [ebp-4],10h

    01002806 e8bf050000      call    ntdbghang1+0x2dca (01002dca)

     

    Store the result of func1 in esi (call it localvar2)

    0100280b 8bf0            mov     esi,eax

     

    Call func2(localvar2, &localvar1) [func2 address at 0100b484]

    0100280d 59              pop     ecx

    0100280e 8d45fc          lea     eax,[ebp-4]

    01002811 50              push    eax

    01002812 56              push    esi

    01002813 e86c8c0000      call    ntdbghang1+0xb484 (0100b484)

     

    If func2 returns 0, then goto 01002821

    01002818 85c0            test    eax,eax

    0100281a 7405            je      ntdbghang1+0x2821 (01002821)

     

    Call func3() [func3 address at 0100278d]

    ntdbghang1+0x281c:

    0100281c e86cffffff      call    ntdbghang1+0x278d (0100278d)

     

    Call func4(localvar2) [func4 address at 01002ce3]

    ntdbghang1+0x2821:

    01002821 56              push    esi

    01002822 e8bc040000      call    ntdbghang1+0x2ce3 (01002ce3)

     

    Clean up and exit the function

    01002827 59              pop     ecx

    01002828 5e              pop     esi

    01002829 c9              leave

    0100282a c3              ret

     

     

    So let’s translate this to some pseudo-code...

     

    localvar1 = 0x10;

    localvar2 = func1(0x20);

     

    if(func2(localvar2, &localvar1)

    {

           func3();

     

    func4(localvar2);

     

    So the behavior of the function will differ, depending on the results of func2.  Let’s see if we can figure out what func2 does...

     

    0:001> u 0100b484

    ntdbghang1+0xb484:

    0100b484 ff2568110001    jmp     dword ptr [ntdbghang1+0x1168 (01001168)]

    0100b48a cc              int     3

    0100b48b cc              int     3

    0100b48c cc              int     3

     

    0:001> dps 01001168 L1

    01001168  70b88cb1 WINSPOOL!GetDefaultPrinterW

     

     

    GetDefaultPrinterW is a public API function.  Here’s the function prototype from MSDN...

     

    BOOL GetDefaultPrinter(

      LPTSTR pszBuffer,   // printer name buffer

      LPDWORD pcchBuffer  // size of name buffer

    );

     

    This fits our pseudo-code, since the function takes two parameters and returns a BOOL.  Let’s update our pseudo code to match what we know, replacing func2 with GetDefaultPrinter, etc...

     

    DWORD cchBuffer = 0x10;

    LPWSTR pszBuffer = func1(0x20);

     

    if(GetDefaultPrinterW(pszBuffer,  &cchBuffer))

    {

           func3();

    }

     

    func4(pszBuffer);

     

    Based on the above, we can make a couple of assumptions.  Func1 is likely an allocator function of some kind (such as malloc) and func4 is likely a memory free function (such as free). Since the app is using the Unicode version of GetDefaultPrinter (it ends with a W) it make sense that func1 is an allocator asking for 0x20 bytes, and the size of the buffer, in characters, passed to GetDefaultPrinterW is 0x10.  So that accounts for all of the functions, except for func3.  We could unassemble func3 to see what it does, but that may not be needed.  From the pseudo-code we’ve already created, we can see that a failure in GetDefaultPrinterW will prevent the button click function from doing anything except allocating and freeing some memory.  So GetDefaultPrinterW is a likely potential point of failure.

     

    Let’s test this theory out.  We’ll set a breakpoint on GetDefaultPrinterW and see if it is failing upon the button click.

     

    0:001> bp WINSPOOL!GetDefaultPrinterW

     

    0:001> g

     

    <Now click Button 1>

     

    Breakpoint 0 hit

    eax=0006fb84 ebx=00000000 ecx=00000020 edx=00dc0e98 esi=00dc0e70 edi=0006fc0c

    eip=70b88cb1 esp=0006fb74 ebp=0006fb88 iopl=0         nv up ei pl nz na po nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202

    WINSPOOL!GetDefaultPrinterW:

    70b88cb1 8bff            mov     edi,edi

     

    // Dump out the call stack...

    0:000> kb

    ChildEBP RetAddr  Args to Child             

    0006fb70 01002818 00dc0e70 0006fb84 00000111 WINSPOOL!GetDefaultPrinterW

    WARNING: Stack unwind information not available. Following frames may be wrong.

    0006fb88 0100287c 0006fbbc 75d41a10 00320f78 ntdbghang1+0x2818

    0006fb90 75d41a10 00320f78 00000111 00000101 ntdbghang1+0x287c

    0006fbbc 75d41ae8 01002830 00320f78 00000111 USER32!InternalCallWinProc+0x23

    0006fc34 75d4286a 00000000 01002830 00320f78 USER32!UserCallWinProcCheckWow+0x14b

    0006fc74 75d42bba 00a90b80 0095ee08 00000101 USER32!SendMessageWorker+0x4b7

     

    // Go to the return address.  Note that eax=0, meaning GetDefaultPrinterW returned FALSE.

    0:000> gu

    eax=00000000 ebx=00000000 ecx=76f22033 edx=00e10178 esi=00dc0e70 edi=0006fc0c

    eip=01002818 esp=0006fb80 ebp=0006fb88 iopl=0         nv up ei pl zr na pe nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246

    ntdbghang1+0x2818:

    01002818 85c0            test    eax,eax

     

    // Check the last error...

    0:000> !gle

    LastErrorValue: (Win32) 0x7a (122) - The data area passed to a system call is too small.

     

           // Resume execution

    0:000> g

     

    The error returned was 0x7a = ERROR_INSUFFICIENT_BUFFER.  It looks like the buffer of 0x20 bytes being passed to GetDefaultPrinterW is too small to hold the name of the default printer for that user.  This explains why the app works for some users and fails for others.  A quick change of the default printer name to something less than 0x10 characters (16 decimal) will work around this issue.

     

    To wrap things up, here is the C source for the Button1_OnClick function (at address 010027f6 in the assembly) so you can see how this was actually written...

     

    VOID Button1_OnClick()

    {

          DWORD cch = 16;

          LPTSTR pPrinterName;

     

          pPrinterName = (LPTSTR) malloc(16 * sizeof(TCHAR));

     

          if(GetDefaultPrinter(pPrinterName, &cch))

          {

                DisplayGoButtonMessage();

          }

     

          free(pPrinterName);

     

          return;

    }

     

    Look for an upcoming blog post that shows another way this problem could have been approached – using the “wt” command in the debugger.  I hope you found this useful and can apply to real-world debugging scenarios.  Please post any questions / comments!

  • Ntdebugging Blog

    Getting Ready for Windows Debugging

    • 8 Comments

     

    Welcome to the Microsoft NTDebugging blog!  I’m Matthew Justice, an Escalation Engineer on Microsoft’s Platforms Critical Problem Resolution (CPR) team.  Our team will be blogging about troubleshooting Windows problems at a low level, often by using the Debugging Tools for Windows.  For more information about us and this blog, check out the about page.

     

    To get things started I want to provide you with a list of tools that we’ll be referencing in our upcoming blog posts, as well as links to some technical documents to help you get things configured.

     

    The big list of tools:

     

    The following tools are part of the “Debugging Tools for Windows” – you’ll definitely need these

    http://www.microsoft.com/whdc/devtools/debugging/

    ·         windbg

    ·         cdb

    ·         ntsd

    ·         tlist

    ·         gflags

    ·         adplus

    ·         UMDH

    ·         symcheck

     

    Sysinternals provides some great tools that we’ll be discussing

    http://www.sysinternals.com

    ·         Process Explorer

    ·         Process Monitor

    ·         Regmon

    ·         Filemon

    ·         DbgView

    ·         Handle.exe

    ·         Tcpview

    ·         LiveKD

    ·         AutoRuns

    ·         WinObj

     

    There are many tools contained in “MPS Reports” (MPSRPT_SETUPPerf.EXE), but I’m listing it here specifically for Checksym

    http://www.microsoft.com/downloads/details.aspx?FamilyID=CEBF3C7C-7CA5-408F-88B7-F9C79B7306C0&displaylang=en

    ·         Checksym

     

    “Windows Server 2003 Resource Kit Tools” is another great set of tools.  In particular Kernrate is a part of that package

    http://www.microsoft.com/downloads/details.aspx?displaylang=en&familyid=9D467A69-57FF-4AE7-96EE-B18C4790CFFD

    ·         Kernrate

     

    Windows XP SP2 Support Tools

    http://www.microsoft.com/downloads/details.aspx?FamilyID=49AE8576-9BB9-4126-9761-BA8011FABF38&displaylang=en

    ·         netcap

    ·         poolmon

    ·         memsnap

    ·         tracefmt  (64-bit versions available in the DDK)

    ·         tracelog

    ·         tracepdb

    ·         depends

    ·         pstat

     

    “Visual Studio “ – in addition to the compilers and IDE, the following tools come in handy:

    ·         SPY++

    ·         dumpbin

     

    Perfwiz (Performance Monitor Wizard)

    http://www.microsoft.com/downloads/details.aspx?FamilyID=31fccd98-c3a1-4644-9622-faa046d69214&DisplayLang=en

     

    DebugDiag

    http://www.iis.net/handlers/895/ItemPermaLink.ashx

     

    Userdump (User Mode Process Dumper)

    http://www.microsoft.com/downloads/details.aspx?FamilyID=E089CA41-6A87-40C8-BF69-28AC08570B7E&displaylang=en

     

    Dheapmon (Desktop Heap Monitor)

    http://www.microsoft.com/downloads/details.aspx?familyid=5CFC9B74-97AA-4510-B4B9-B2DC98C8ED8B&displaylang=en

     

    Netmon 3.0

    §  Go to http://connect.microsoft.com/

    §  Sign in with your passport account

    §  Choose "Available Connections" on the left

    §  Choose "Apply for Network Monitor 3.0” (once you've finished with the application, the selection appears in your "My Participation" page)

    §  Go to the Downloads page (On the left side), and select the appropriate build 32 or 64 bit build.

     

     

     

    Some articles you may find useful:

     

    Debugging Tools and Symbols: Getting Started

    http://www.microsoft.com/whdc/devtools/debugging/debugstart.mspx

     

    Boot Parameters to Enable Debugging

    http://msdn2.microsoft.com/en-us/library/ms791527.aspx

     

    How to Generate a Memory Dump File When a Server Stops Responding (Hangs)

    http://support.microsoft.com/kb/303021/

     

    After installing the “Debugging Tools for Windows”, you’ll find two documents at the root of the install folder that are helpful:

     

    ·         kernel_debugging_tutorial.doc - A guide to help you get started using the kernel debugger.

     

    ·         debugger.chm - The help file for the debuggers.  It details the commands you can use in the debugger.  Think of this as a reference manual, rather than a tutorial.





  • Ntdebugging Blog

    Hardware bitflipping

    • 8 Comments

    Hello all; my name is Scott Olson and I work as an Escalation Engineer for Microsoft Global Escalation Services team in Platforms support, and I wanted to share an interesting problem that came up recently. A co-worker was running Windows Vista Ultimate x64 on their home machine and ran into a problem where the system would get random bugchecks after upgrading the RAM from 2GB to 4GB. Any combination of the RAM with 2GB was fine; however with 4GB of RAM installed the system would bugcheck within 10 minutes of booting. Once I heard about this I wanted to look at the memory dump in kernel debugger.

    Here's is what I found:

    The system got the following bugcheck:

    0: kd> .bugcheck
    Bugcheck code 000000D1
    Arguments fffff800`03a192d0 00000000`00000002 00000000`00000000 fffff980`064aa8b6

    Tip: The help file included with the Debugging Tools For Windows contains a Bug Check Code Reference that includes details on how to parse the Bug Check code and its arguments. See: Help > Debugging Techniques > Bug Checks (Blue Screens) > Bug Check Code Reference

    !analyze -v provides the following information for this bugcheck:

    DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
    An attempt was made to access a pageable (or completely invalid) address at an interrupt request level (IRQL) that is too high. This is usually caused by drivers using improper addresses. If kernel debugger is available get stack backtrace.
    Arguments:
    Arg1: fffff80003a192d0, memory referenced
    Arg2: 0000000000000002, IRQL
    Arg3: 0000000000000000, value 0 = read operation, 1 = write operation
    Arg4: fffff980064aa8b6, address which referenced memory

    Debugging Details:
    ------------------

    READ_ADDRESS: fffff80003a192d0

    CURRENT_IRQL: 2

    So with this data I can say that the system took a page fault on a read operation trying to reference the memory at fffff80003a192d0 at DISPATCH_LEVEL. OK, so let's get the trap frame so we can get into context of the system when the crashed happened:

    0: kd> kv 3
    Child-SP RetAddr : Args to Child : Call Site
    fffff800`03218f28 fffff800`0204da33 : 00000000`0000000a fffff800`03a192d0 00000000`00000002 00000000`00000000 : nt!KeBugCheckEx
    fffff800`03218f30 fffff800`0204c90b : 00000000`00000000 fffffa80`0a3c6cf0 00000000`00000000 00000000`00000000 : nt!KiBugCheckDispatch+0x73
    fffff800`03219070 fffff980`064aa8b6 : 00000000`00000002 00000000`00000000 00000000`000005e0 fffff800`03219220 : nt!KiPageFault+0x20b (TrapFrame @ fffff800`03219070)

    Here is the trap frame and it looks like system crashed while trying to reference memory at an offset from the stack pointer, rsp+0xD0 (highlighted above)

    0: kd> .trap fffff800`03219070
    NOTE: The trap frame does not contain all registers.
    Some register values may be zeroed or incorrect.
    rax=0000000000000000 rbx=0000000000000010 rcx=0000000000000011
    rdx=0000000000000002 rsi=0000000000000000 rdi=0000000000000001
    rip=fffff980064aa8b6 rsp=fffff80003219200 rbp=00000000000071d6
    r8=fffff80003219280 r9=00000000000071d6 r10=0000000000000000
    r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
    r14=0000000000000000 r15=0000000000000000
    iopl=0 nv up ei pl zr na po nc
    tcpip!InetInspectReceiveDatagram+0xf6:
    fffff980`064aa8b6 440fb78c24d0000000 movzx r9d,word ptr [rsp+0D0h] ss:0018:fffff800`032192d0=8c13

    As you can see above fffff800`032192d0 looks like valid memory and shouldn't normally cause a page fault on a read operation. At this point, I want to make sure the system did what it was told. I want to know what happened when the system trapped. To verify the faulting address I dumped the CR2 register to see what address was referenced when the page fault happened; this is also the first parameter in the bugcheck code for a stop 0xd1.

    0: kd> r cr2
    cr2=fffff80003a192d0

    Looking at this address it is clear that the trap frame does not exactly match, so let's look at how these addresses are different. Here is the stack pointer from the trap frame and the page fault converted into varying formats (focusing on the binary)

    0: kd> .formats fffff800`032192d0
    Evaluate expression:
    Hex: fffff800`032192d0
    Decimal: -8796040490288
    Octal: 1777777600000310311320
    Binary: 11111111 11111111 11111000 00000000 00000011 00100001 10010010 11010000
    Chars: .....!..
    Time: ***** Invalid FILETIME
    Float: low 4.74822e-037 high -1.#QNAN
    Double: -1.#QNAN

    0: kd> .formats fffff800`03a192d0
    Evaluate expression:
    Hex: fffff800`03a192d0
    Decimal: -8796032101680
    Octal: 1777777600000350311320
    Binary: 11111111 11111111 11111000 00000000 00000011 10100001 10010010 11010000
    Chars: ........
    Time: ***** Invalid FILETIME
    Float: low 9.49644e-037 high -1.#QNAN
    Double: -1.#QNAN

    Notice that there is a one bit difference between these 2 addresses

    11111111 11111111 11111000 00000000 00000011 00100001 10010010 11010000

    11111111 11111111 11111000 00000000 00000011 10100001 10010010 11010000

    Since the software asked the system to do one thing and it did something different this is clearly some type of hardware problem (most likely with the processor). I reported this back to the co-worker and they contacted their hardware vendor. This must have been a common problem with this vendor because I found out later that they replied back within 10 minutes of contacting them with a recommendation to change the memory voltage in the BIOS. The memory voltage was set to Auto, which is a default. They recommended it be changed from 1.85 volts to 2.1 volts. After making the change the system was stable with 4GB of RAM.

  • Ntdebugging Blog

    Basics of Debugging Windows

    • 8 Comments

    Hello, this is East again. This blog post is about a topic that we always skip over when discussing debugging; what and where are the tools for debugging. I will touch on the different types of debuggers, loading symbols and the basics of getting started with loading up a dump under your preferred debugger.

    Microsoft currently offers 4 types of debugging tools. With these tools you can remote debug another machine over firewire or serial cable (USB also but may not work consistently), as well as debug usermode processes and dump files.

    Command line debuggers:

    1 ) kd.exe: kernel debugger – Used to review Crash dumps created by a blue screen crash event or a stop error. (kd –z <location of dump> –y <location of symbols>)

    2 ) cdb.exe: User mode debugger for reviewing applications,  processes, and process dumps  (cdb  –z <location of dump> –y <location of symbols> )

    3 ) ntsd.exe: CDB and NTSD are virtually identical, except that NTSD spawns a new text window when it is started, whereas CDB inherits the Command Prompt window from which it was invoked.  When I refer to "CDB", it applies to both CDB and NTSD.

    Graphical User Interface Debugger:

    4) Windbg.exe is a GUI based debugger. It can debug the same things as KD & CDB using the same commands. Windbg gives you the ability to have multiple windows open simultaneously  to review source code or other selectable items under the view menu.

    I like using windbg for all of my user and kernel debugging, while  others I work with prefer kd for kernel debugging and cdb for user mode debugging.

     

    There are 32bit and 64bit debuggers available.

    NOTE: Some people use Visual Studio as well, but this blog post will not cover using Visual Studio as a debugger.

     

    You can review applications that already have started on your machine using CDB or Windbg. You can have the problematic application launch under the debugger as well:

    Cdb or Windbg

    -p <pid> specifies the decimal process ID to attach to ( use tlist or the task manger to obtain the PID)

    -psn <name> specifies the process to attach to by service name

    <application to launch> -y <symbol path>

    NOTE: windbg allows you to use menu options as well: select “Attach to a Process” on the File menu to debug a user-mode application that is currently running.

     

    What are dumps?

    Memory dumps are a record of what was in memory and the registers at the time of a crash. There are 3 types of memory dumps:

    NOTE: The type of dump that will be written upon bugcheck can be configured by right clicking my computer ->properties ->Advanced tab ->Settings, in the Write debugging section you will use the first drop down box to select what type of memory dump you want. (See KB307973)

    ·         Mini dump – is a subset of memory that is in use by the application creating the dump.

    A mini memory Dump file is written to %SystemRoot%\Minidump\Memory.dmp by default and is usually less than a 1mb in size.

    ·         Kernel only – This is used to review the machine’s kernel memory at the time of the crash.

    ·         Full/Complete – This is the largest kernel mode dump file. It contains all information from kernel and user mode address spaces that was in physical memory at the time of the dump (about the same size as the physical memory on the box).

    Kernel and Complete Memory Dumps are written to %SystemRoot%\Memory.dmp by default.

    Note: You can configure the server to crash using certain keystrokes . This would be useful when troubleshooting a hung server or a timing issue, KB244139 explains how to configure your server for a manual crash.

    You can also create dump files from an application or process, these are known as User-mode dumps.  Additional information can be found on these types dump in the Debugging Tools for Windows help file.

     

    How do I read a dump file?

    In order to make fast progress with a memory dump file, it is best to load symbol files. Symbol files contains data that the debugger uses to interpret the application or driver code. They may contain:

    -          Global variable names

    -          Function names

    Private Symbols would contain the above information and:

    -          Local variable names

    -          Source-line numbers

    -          Type information for variables, structures, etc.

     Microsoft currently has two ways you can access symbols for the Operating System:

    Service pack download site – You will need to create:

    -          Separate directories for Windows 2000 RTM, Windows 2000 SP1, Windows 2000 SP2, Windows XP RTM, etc.

    -          Separate directories for all of the above for free vs. checked build

    -          Separate directories for hotfix symbols

     

    Public symbol server – uses a symbol store, which is a collection of symbol files. The symbol server uses the time stamp & file size to match up symbols to the active binary.After getting your symbol files together, you will need a way to tell the debugger where they are located and set up some other options.

    To set the symbol path do one of the following:

    -          _NT_SYMBOL_PATH environment variable

    -          -y command line option

    -          .sympath (Set Symbol Path) debugger command

    -          WinDbg: File | Symbol File Path dialog, or CTRL+S

    To set the executable Image Path (needed for minidumps only), do one of the foolowing:

    -          -i command line option

    -          .exepath debugger command

    -          WinDbg: File | Image File Path dialog, or CTRL+i

    -          Source Path

    -          .srcpath WinDbg: File | Source File Path dialog, or CTRL+P

    If symbol errors appear when you begin, you can try the below commands to help narrow down some problems;

    !sym noisy — gives verbose symbol information

    AND

    .reload —  to reload all symbols

     

    Also using the srv* in your symbol path tells the debugger to load and save symbols being used out to a specific directory:

    srv*DownstreamStore*<symbol locations>

     

    NOTE: You must always use .reload after you change the symbol path or fix a symbol error — the debugger doesn’t automatically reload your symbols!

     

    Now that we are done with the overview, let’s configure our machine as a host computer to open memory a dump.  I will be using Microsoft Public Symbol servers and I want to store current symbols locally to my host machine.

    Using windbg I will set my current workspace symbols to: srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols

    Click the menu option File ->Symbol File Path or Ctrl + S. This will bring up an empty box that will allow you to enter or browse to your symbol path.

    If using kd you want to set an environment variable (_NT_SYMBOL_PATH) under “my computer properties -> advanced tab” to always start with your symbols set to:  “srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols” or use this same path in your command line:

    Kd –z <path to dump.file> -y srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols

     

    NOTE: Windbg will append any workspace symbol path with the one set by the _NT_SYMBOL_PATH environment variable during loading of a memory dump.

    Ok, now we know what debugger we want to use and we know our symbol locations. Let’s open our first kernel memory dump , located on <drive letter> <path to dump file>

    Using windbg, I will load a dump file using menu options File ->Open crash Dump (ctrl + D) or drag the the dump file into the debugger; you can even  start windbg at the command prompt.  My command would look like this:

    Windbg  –z C:\training\case 7f\MEMORY051308.22.DMP

    I did not use the –y for symbol path, as it is set already in my default workspace or in my environment variable.

    When the debugger first loads a dump file it displays several lines of information before giving you a prompt to get started with your commands (by default):

    Microsoft (R) Windows Debugger Version 6.9.0003.113 X86  ß debugger version

    Copyright (c) Microsoft Corporation. All rights reserved. ß Copyright of the debugger creator

    Loading Dump File [C:\training\case 7f\MEMORY051308.22.DMP] ß location of the dump file loading

    Kernel Summary Dump File: Only kernel address space is available ß type of memory dump (mini, kernel, or full)

    Symbol search path is: srv*c:\pubsymbols*http://msdl.microsoft.com/download/symbols ß Symbol path for this debug session

    Executable search path is:  ß points to the directory the executable files are located. For most situations this is not needed. For other situations please check the debugger help file.

     

    The next 4 lines talk about The OS version, service packs and how many processors are on the box

    1 -Windows Server 2003 Kernel Version 3790 (Service Pack 2) MP (8 procs) Free x86 compatible

    2 - Product: Server, suite: Enterprise TerminalServer SingleUserTS

    3 - Built by: 3790.srv03_sp2_gdr.070304-2240

    4 - Kernel base = 0x80800000 PsLoadedModuleList = 0x808a6ea8

     

    Next we would see when the machine crashed and how long it was up prior to this crash:

    Debug session time: Wed May 14 01:27:36.768 2008 (GMT-4)

    System Uptime: 0 days 16:32:51.921

     

    After completing the above process, the debugger starts loading the dump file and parsing through the loaded symbols. Here you may notice some warnings for some user space processes which are not included in the kernel dump. This is ok.

    WARNING: Process directory table base BFF0A080 doesn't match CR3 007AF000

    WARNING: Process directory table base BFF0A080 doesn't match CR3 007AF000

    Loading Kernel Symbols

    ...........................................................................................................................................

    Loading User Symbols

    PEB is paged out (Peb.Ldr = 7ffdf00c).  Type ".hh dbgerr001" for details

    Loading unloaded module list

    *******************************************************************************

    *                                                                             *

    *                        Bugcheck Analysis                                    *

    *                                                                             *

    *******************************************************************************

     

    1- Use !analyze -v to get detailed debugging information.

    2 - BugCheck 7F, {8, f773ffe0, 0, 0}

    3 - *** ERROR: Module load completed but symbols could not be loaded for ql2300.sy

    The three things I want to point out from above are:

    1 - !analyze –v: This is the debugger command used to help analyze a dump file by reviewing information passed to KeBugCheck including specific parameters of that crash. It will analyze this information and provide a definition of the bugcheck, a stack showing all current function calls, and, when possible, the name of an offending driver or process that the debugger thinks is at fault.  Please review the debugger help file for additional information in this area.

    2 – The type of bugcheck that occurred on the machine.

    3 – An error telling you about symbols missing or not available to help diagnose a particular driver or application. This can lead to a misdiagnostis if you’re not careful.

    Once loading is completed you should be at a kd> prompt. This prompt shows you the current processor you are using (if the machine has more than one).

    For this dump we are at processor 3 on an 8 proc machine:

    3: kd>

     

    To view the current crash stack location you can use the "K" command. There are multiple forms of this command, each one dumping the basic plus additional information. As functions are executed and call other functions, a call stack is created in stack memory. Here are two common commands to view the stack:

     

    3: kd> k

    ChildEBP RetAddr

    00000000 baebf0ce nt!KiTrap08+0x75

    b3a4bffc baebf737 storport!RaCallMiniportInterrupt+0x2

    b3a4c008 8088d889 storport!RaidpAdapterInterruptRoutine+0x1d

    b3a4c008 80a59d8e nt!KiInterruptDispatch+0x49

    b3a4c09c 80a5c2fc hal!HalpGenerateInterrupt+0x1d2

    b3a4c0c0 80a5c44d hal!HalpLowerIrqlHardwareInterrupts+0x108

    b3a4c0d0 808256ed hal!KfLowerIrql+0x59

    <snippet>

     

    3: kd> kb

    ChildEBP RetAddr  Args to Child

    00000000 baebf0ce 00000000 00000000 00000000 nt!KiTrap08+0x75

    b3a4bffc baebf737 97bedb88 b3a4c02c 8088d889 storport!RaCallMiniportInterrupt+0x2

    b3a4c008 8088d889 977b9e18 97bedad0 03010006 storport!RaidpAdapterInterruptRoutine+0x1d

    b3a4c008 80a59d8e 977b9e18 97bedad0 03010006 nt!KiInterruptDispatch+0x49

    b3a4c09c 80a5c2fc 97797004 97bedad0 00000102 hal!HalpGenerateInterrupt+0x1d2

    b3a4c0c0 80a5c44d 00000101 977b9e02 b3a4c0d8 hal!HalpLowerIrqlHardwareInterrupts+0x108

    b3a4c0d0 808256ed b3a4c0e8 baebf1c6 977b9bb0 hal!KfLowerIrql+0x59

    <snippet>

     

    Either one can be used depending on how much information you want to see and can use.

    This completes the Basic of Debugging Windows, Part I. I will create a Part II using specific questions gathered from our readers.

     

    Miscellaneous information:

    To go further with this topic I would suggest starting with the debugger help file included with the Microsoft Debugging Tools. 

    ADPlus – An automated way to use the cdb.exe to capture/create a usermode dump when a process hangs or crashes. (more info - http://msdn.microsoft.com/en-us/library/cc265629.aspx or kb286350)

    Public Symbols for Microsoft Operating Systems:

    Microsoft Public Symbol server : srv * DownstreamStore * http://msdl.microsoft.com/download/symbols

    example: srv*c:\mysyms*http://msdl.microsoft.com/download/symbols

     Microsoft Symbol packages http://www.microsoft.com/whdc/devtools/debugging/symbolpkg.mspx#d

    Use !Analyze-v to gather additional information about the bugcheck and a bucket-id for your dump file. The bucket-id can be submitted to Microsoft for review for similar crashes and resolutions. Try using the Microsoft Online Crash Analysis to submit your crash dump bucket-id for possible follow up from Microsoft or for Microsoft to look for trends: http://oca.microsoft.com/en/Welcome.aspx

    For concepts, tools and information about the system architecture:

    http://msdn.microsoft.com/en-us/default.aspx

    Windows Internal 4th edition (by Mark E. Russinovich & David A. Solomon) the whole book or Chapter 14 - Crash Dump Analysis

    Advanced Windows Debugging (by Mario Hewardt & Daniel Pravat )

    http://technet.microsoft.com/en-us/default.aspx

  • Ntdebugging Blog

    Challenges of Debugging Optimized x64 Code

    • 8 Comments

    If you have not had the luxury of debugging optimized x64 code as of yet, don’t wait much longer and fall behind the times!  Due to the x64 fastcall-like calling convention coupled with the abundance of general purpose registers, finding variable values at arbitrary points in a call stack can be very tricky indeed.

    In this article, I’d like to detail some of my favorite techniques for debugging optimized x64 code.  But before digging into these techniques, let’s first have a quick overview of the x64 calling convention.

    The x64 Calling Convention

    Those of you familiar with the fastcall calling convention on x86 platforms will recognize the similarities to the x64 calling convention.  Whereas you typically have to maintain knowledge of multiple calling conventions on x86 platforms, on x64 platforms there is currently just one.  (Of course, I’m excluding the case of no calling convention which one can achieve with __declspec(naked) or by coding in straight assembly.)

    I won’t go into all of the various nuances of the x64 calling convention, therefore I recommend you check out the following link (http://msdn.microsoft.com/en-us/library/ms794533.aspx).  But commonly, the first four parameters into a function are passed via the registers rcx, rdx, r8, and r9.  If the function accepts more than four parameters, those parameters are passed on the stack.  (Those of you familiar with the x86 fastcall calling convention where the first two parameters are passed in ecx and edx will recognize the similarities).

    To help illustrate how the x64 calling convention works, I have created some simple example code.  Although the code is contrived and far from real-world code, it demonstrates some scenarios that are likely to encounter in the real word.  The code is shown below.

    #include <stdlib.h>

    #include <stdio.h>

    #include <windows.h>

    __declspec(noinline)

    void

    FunctionWith4Params( int param1, int param2, int param3,

                         int param4 )

    {

        size_t lotsOfLocalVariables1 = rand();

        size_t lotsOfLocalVariables2 = rand();

        size_t lotsOfLocalVariables3 = rand();

        size_t lotsOfLocalVariables4 = rand();

        size_t lotsOfLocalVariables5 = rand();

        size_t lotsOfLocalVariables6 = rand();

        DebugBreak();

        printf( "Entering FunctionWith4Params( %X, %X, %X, %X )\n",

                param1, param2, param3, param4 );

        printf( "Local variables: %X, %X, %X, %X, %X, %X \n",

                lotsOfLocalVariables1, lotsOfLocalVariables2,

                lotsOfLocalVariables3, lotsOfLocalVariables4,

                lotsOfLocalVariables5, lotsOfLocalVariables6 );

    }

    __declspec(noinline)

    void

    FunctionWith5Params( int param1, int param2, int param3,

                         int param4, int param5 )

    {

        FunctionWith4Params( param5, param4, param3, param2 );

        FunctionWith4Params( rand(), rand(), rand(), rand() );

    }

    __declspec(noinline)

    void

    FunctionWith6Params( int param1, int param2, int param3,

                         int param4, int param5, int param6 )

    {

        size_t someLocalVariable1 = rand();

        size_t someLocalVariable2 = rand();

        printf( "Entering %s( %X, %X, %X, %X, %X, %X )\n",

                "FunctionWith6Params",

                param1, param2, param3, param4, param5, param6 );

        FunctionWith5Params( rand(), rand(), rand(),

                             param1, rand() );

        printf( "someLocalVariable1 = %X, someLocalVariable2 = %X\n",

                someLocalVariable1, someLocalVariable2 );

    }

    int

    main( int /*argc*/, TCHAR** /*argv*/ )

    {

        // I use the rand() function throughout this code to keep

        // the compiler from optimizing too much.  If I had used

        // constant values, the compiler would have optimized all

        // of these away.

        int params[] = { rand(), rand(), rand(),

                         rand(), rand(), rand() };

        FunctionWith6Params( params[0], params[1], params[2],

                             params[3], params[4], params[5] );

        return 0;

    }

     

    Cut and paste this code into a cpp file (such as example.cpp).  I used the Windows SDK (specifically the Windows SDK CMD Shell) to compile this code as C++ code by using the following command line:

    cl /EHa /Zi /Od /favor:INTEL64 example.cpp /link /debug

    Notice the /Od switch.  This disables all optimizations.  Later on, I’ll enable maximum optimization and that’s when the fun begins!

    Once you have the executable module built (mine is named example.exe), then you can fire it up in the debugger as follows:

    windbg -Q -c "bu example!main;g;" example.exe

    The command above will launch the application in windbg, set a breakpoint on the main() routine, and then go to that breakpoint.

    Now, let’s have a look at a diagram of what the stack looks like when FunctionWith6Params() gets called.  The diagram shown below illustrates the stack when the instruction pointer is at the beginning of the code for FunctionWith6Params() but before the prolog code has executed:

    CallStack1

    Notice that the caller, in this case main(), allocated enough space on the stack for all six parameters to FunctionWith6Params() even though the first four parameters are passed in via registers.  The extra space on the stack is commonly referred to as the “home space” for the register parameters.  In the previous diagram, I have shown those slots filled with xxxxxxxx to indicate that the values within there are virtually random at this point.  That’s because the caller, main(), does not initialize these slots.  The called function, at its discretion, may store the first four parameters in this space for safe keeping.  This is exactly what happens in non-optimized builds and is a huge debugging convenience since you can easily find the contents of the first four parameters on the stack if you need to.  Additionally, windbg stack commands such as kb and kv which show these first few parameters will report true results.

    With all of that said, here is what the stack looks like after the prolog code in FunctionWith6Params() executes:

    CallStack2

    The prolog assembly code for FunctionWith6Params() is shown below:

    0:000> uf .

    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 28]:

       41 00000001`40015900 mov     dword ptr [rsp+20h],r9d
       41 00000001`40015905 mov     dword ptr [rsp+18h],r8d
       41 00000001`4001590a mov     dword ptr [rsp+10h],edx
       41 00000001`4001590e mov     dword ptr [rsp+8],ecx
       41 00000001`40015912 push    rbx
       41 00000001`40015913 push    rsi
       41 00000001`40015914 push    rdi
       41 00000001`40015915 sub     rsp,50h

    You can see that the first four instructions save the first four parameters on the stack in the home space allocated by main().  Then, the prolog code saves any non-volatile registers that FunctionWith6Params() plans to use during its execution.  The saved registers’ states are restored in the function epilog code prior to returning to the caller.  Finally the prolog code reserves some space on the stack, in this case, for 0x50 bytes.

    What is this space reserved on the top of the stack for?  First, space is created for any local variables.  In this case, FunctionWith6Params() has two.  However, those two local variables only account for 0x10 bytes.  What’s the deal with the rest of the space created on the top of the stack?

    On the x64 platform, when code prepares the stack for calling another function, it does not use push instructions to put the parameters on the stack as is commonly the case in x86 code.  Instead, the stack pointer typically remains fixed for a particular function.  The compiler looks at all of the functions the code in the current function calls, it finds the one with the maximum number of parameters, and then creates enough space on the stack to accommodate those parameters.  In this example, FunctionWith6Params() calls printf() passing it 8 parameters.  Since that is the called function with the maximum number of parameters, the compiler creates 8 slots on the stack.  The top four slots on the stack will then be the home space used by any functions FunctionWith6Params() calls.

    A handy side effect of the x64 calling convention is that once you are inside the bracket of the prolog and epilog of a function, the stack pointer does not change while the instruction pointer is in that function.  This eliminates the need for a base pointer which is common in x86 calling conventions.  When the code in FunctionWith6Params() prepares to call a child function, it simply puts the first four parameters into the required registers and, if there are more than 4 parameters, it uses mov instructions to place the remaining parameters in the allocated stack space but making sure to skip the first four parameter slots on the stack.

    Debugging Optimized x64 code (The Nightmare Begins)

    Why is debugging x64 optimized code so tricky?  Well, remember that home space that the caller creates on the stack for the callee to save the first four parameters?  It turns out that the calling convention does not require the callee to use that space!  And you can certainly bet that optimized x64 code will not use that space unless it is necessary and convenient for its optimization purposes.  Moreover, when optimized code does use the home space, it could use it to store non-volatile registers rather than the first four parameters to the function.

    Go ahead and recompile the example code using the following command line:

    cl /EHa /Zi /Ox /favor:INTEL64 example.cpp /link /debug

    Notice the use of the /Ox switch.  This turns on maximum optimization.  Debug symbols are still turned on so we can debug the optimized code easily.  Always build your release product with debug information turned on so you can debug your release builds!

    Let’s look at how the prolog assembly code for FunctionWith6Params() has changed:

       41 00000001`400158e0 mov     qword ptr [rsp+8],rbx
       41 00000001`400158e5 mov     qword ptr [rsp+10h],rbp
       41 00000001`400158ea mov     qword ptr [rsp+18h],rsi
       41 00000001`400158ef push    rdi
       41 00000001`400158f0 push    r12
       41 00000001`400158f2 push    r13
       41 00000001`400158f4 sub     rsp,40h
       41 00000001`400158f8 mov     ebx,r9d
       41 00000001`400158fb mov     edi,r8d
       41 00000001`400158fe mov     esi,edx
       41 00000001`40015900 mov     r12d,ecx

    The optimized code is significantly different!  Let’s itemize the changes below:

    ·         The function uses the home space on the stack, however, it does not store the first four parameters there.  Instead it uses the space to store some non-volatile registers it must restore later in the epilog code.  This optimized code is going to make use of more processor registers, therefore it must save more of the non-volatile registers.

    ·         It still pushes three non-volatile registers onto the stack for safe keeping along with the other three it stored in the home space.

    ·         It then creates space on the stack.  However, it’s less space than in the non-optimized code, and is only 0x40 bytes.  That’s because the optimized code uses registers to represent the local variables someLocalVariable1 and someLocalVariable2.  Therefore, it only has to create space for the 8 slots needed to call the function with the maximum number of parameters, printf().

    ·         It then stores the first four parameters into non-volatile registers rather than in the home space. (Don’t count on this behavior.  An optimized function may make no copies of the contents of rcx, rdx, r8, and r9.  It all depends on the structure of the code)

    Now step through FunctionWith6Params() to the source line just after the first printf() call.  The output generated from the printf() call on my machine is as follows:

    Entering FunctionWith6Params( 29, 4823, 18BE, 6784, 4AE1, 3D6C )

    A common version of the stack command in windbg is kb, which also displays the first few parameters to each function in the frame.  In reality, it is displaying the first few positions of the stack.  The output for the kb command is as follows:

    0:000> kb
    RetAddr           : Args to Child                                                           : Call Site
    00000001`4001593b : 00000000`00004ae1 00000000`00004823 00000000`000018be 00000000`007e3570 : example!FunctionWith6Params+0x6a [c:\temp\blog_entry\sample_code\example.cpp @ 37]
    00000001`40001667 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000001 : example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 57]
    00000000`76d7495d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : example!__tmainCRTStartup+0x15b
    00000000`76f78791 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
    00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

    Notice that not all of the first four parameters of FunctionWith6Params() match what is shown by the kb command!  Of course, this is a side effect of the optimization.  You simply cannot trust the output displayed by kb and kv in optimized code.  This is the biggest reason why optimized x64 code is so difficult to debug.  Trust me when I say that it’s just pure luck that the second and third slots in the kb output above match the actual parameter values to FunctionWith6Params().  It’s because FunctionWith6Params() stores non-volatile registers in those slots and it just so happens that main() put those values in those non-volatile registers prior to calling FunctionWith6Params().

    Parameter Sleuthing -- Technique 1 (Down the Call Graph)

    Now, let’s look at some techniques for finding elusive function parameters to functions in the call stack while running x64 code.  I have placed a DebugBreak() call in FunctionWith4Params() to illustrate.  Go ahead and let the code run in windbg until it hits this breakpoint.  Now, imagine what you are looking at is actually not a live debugging scenario but rather a dump file from a customer of yours and this is the point where your application has crashed.  So, you take a look at the stack and it looks like the following:

    0:000> kL
    Child-SP          RetAddr           Call Site
    00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    00000000`0012fee0 00000001`4000168b example!main+0x5b
    00000000`0012ff20 00000000`7733495d example!__tmainCRTStartup+0x15b
    00000000`0012ff60 00000000`77538791 kernel32!BaseThreadInitThunk+0xd
    00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    Now, let’s say that in order for you to figure out what went wrong, you need to know the first parameter to FunctionWith6Params().  Assume you have not seen the first parameter in the console output. No fair cheating!

    The first technique I would like to illustrate involves digging downward into the call graph  to find out what has happened to the contents of rcx (the first parameter) after entering FunctionWith6Params().  In this case, since the parameters are 32bit integers, we’ll be attempting to follow the contents of ecx, which is the lower half of rcx.

    Let’s start by looking at the assembly code within FunctionWith6Params() starting from the beginning up to the call into FunctionWith5Params()::

    0:000> u example!FunctionWith6Params example!FunctionWith6Params+0x97
    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
    00000001`400158e0 mov     qword ptr [rsp+8],rbx
    00000001`400158e5 mov     qword ptr [rsp+10h],rbp
    00000001`400158ea mov     qword ptr [rsp+18h],rsi
    00000001`400158ef push    rdi
    00000001`400158f0 push    r12
    00000001`400158f2 push    r13
    00000001`400158f4 sub     rsp,40h
    00000001`400158f8 mov     ebx,r9d
    00000001`400158fb mov     edi,r8d
    00000001`400158fe mov     esi,edx
    00000001`40015900 mov     r12d,ecx
    00000001`40015903 call    example!rand (00000001`4000148c)
    00000001`40015908 movsxd  r13,eax
    00000001`4001590b call    example!rand (00000001`4000148c)
    00000001`40015910 lea     rdx,[example!`string'+0x68 (00000001`40020d40)]
    00000001`40015917 movsxd  rbp,eax
    00000001`4001591a mov     eax,dword ptr [rsp+88h]
    00000001`40015921 lea     rcx,[example!`string'+0x80 (00000001`40020d58)]
    00000001`40015928 mov     dword ptr [rsp+38h],eax
    00000001`4001592c mov     eax,dword ptr [rsp+80h]
    00000001`40015933 mov     r9d,esi
    00000001`40015936 mov     dword ptr [rsp+30h],eax
    00000001`4001593a mov     r8d,r12d
    00000001`4001593d mov     dword ptr [rsp+28h],ebx
    00000001`40015941 mov     dword ptr [rsp+20h],edi
    00000001`40015945 call    example!printf (00000001`400012bc)
    00000001`4001594a call    example!rand (00000001`4000148c)
    00000001`4001594f mov     edi,eax
    00000001`40015951 call    example!rand (00000001`4000148c)
    00000001`40015956 mov     esi,eax
    00000001`40015958 call    example!rand (00000001`4000148c)
    00000001`4001595d mov     ebx,eax
    00000001`4001595f call    example!rand (00000001`4000148c)
    00000001`40015964 mov     r9d,r12d
    00000001`40015967 mov     r8d,esi
    00000001`4001596a mov     edx,ebx
    00000001`4001596c mov     ecx,eax
    00000001`4001596e mov     dword ptr [rsp+20h],edi
    00000001`40015972 call    example!ILT+5(?FunctionWith5ParamsYAXHHHHHZ) (00000001`4000100a)

    FunctionWith6Params() copies ecx into r12d to preserve it for later use since the contents must be passed to multiple functions within the body of FunctionWith6Params().  Notice at the point where FunctionWith5Params() is called, the contents of ecx have been copied into both r12d and r9d, however, r9d is volatile so we must be careful with it since it could get overwritten prior to the next function call when FunctionWith5Params() calls FunctionWith4Params().  Armed with this information, let’s dig into the assembly code for FunctionWith5Params() that has executed up to this point:

    0:000> u example!FunctionWith5Params example!FunctionWith5Params+0x20
    example!FunctionWith5Params [c:\temp\blog_entry\sample_code\example.cpp @ 32]:
    00000001`40015880 mov     qword ptr [rsp+8],rbx
    00000001`40015885 mov     qword ptr [rsp+10h],rsi
    00000001`4001588a push    rdi
    00000001`4001588b sub     rsp,20h
    00000001`4001588f mov     ecx,dword ptr [rsp+50h]
    00000001`40015893 mov     eax,r9d
    00000001`40015896 mov     r9d,edx
    00000001`40015899 mov     edx,eax
    00000001`4001589b call    example!ILT+10(?FunctionWith4ParamsYAXHHHHZ) (00000001`4000100f)

    At the point where FunctionWith4Params() is called, the value we are after is now in eax, edx, and r12d.  Again, be careful with eax and edx as they are volatile.  However, since FunctionWith5Params() did not touch r12d, the contents of the parameter we are still after are still in r12d

    Now, let’s look at the code in FunctionWith4Params() that has executed so far:

    0:000> u example!FunctionWith4Params example!FunctionWith4Params+0x66
    example!FunctionWith4Params [c:\temp\blog_entry\sample_code\example.cpp @ 9]:
    00000001`400157b0 48895c2408      mov     qword ptr [rsp+8],rbx
    00000001`400157b5 48896c2410      mov     qword ptr [rsp+10h],rbp
    00000001`400157ba 4889742418      mov     qword ptr [rsp+18h],rsi
    00000001`400157bf 57              push    rdi
    00000001`400157c0 4154            push    r12
    00000001`400157c2 4155            push    r13
    00000001`400157c4 4156            push    r14
    00000001`400157c6 4157            push    r15
    00000001`400157c8 4883ec50        sub     rsp,50h
    00000001`400157cc 458be1          mov     r12d,r9d
    00000001`400157cf 458be8          mov     r13d,r8d
    00000001`400157d2 448bf2          mov     r14d,edx
    00000001`400157d5 448bf9          mov     r15d,ecx
    00000001`400157d8 e8afbcfeff      call    example!rand (00000001`4000148c)
    00000001`400157dd 4898            cdqe
    00000001`400157df 4889442448      mov     qword ptr [rsp+48h],rax
    00000001`400157e4 e8a3bcfeff      call    example!rand (00000001`4000148c)
    00000001`400157e9 4898            cdqe
    00000001`400157eb 4889442440      mov     qword ptr [rsp+40h],rax
    00000001`400157f0 e897bcfeff      call    example!rand (00000001`4000148c)
    00000001`400157f5 4863e8          movsxd  rbp,eax
    00000001`400157f8 e88fbcfeff      call    example!rand (00000001`4000148c)
    00000001`400157fd 4863f0          movsxd  rsi,eax
    00000001`40015800 e887bcfeff      call    example!rand (00000001`4000148c)
    00000001`40015805 4863f8          movsxd  rdi,eax
    00000001`40015808 e87fbcfeff      call    example!rand (00000001`4000148c)
    00000001`4001580d 4863d8          movsxd  rbx,eax
    00000001`40015810 ff15a24b0100    call    qword ptr [example!_imp_DebugBreak (00000001`4002a3b8)]

    We just found what we are looking for!  The red highlighted line shows r12 being saved on the stack because FunctionWith4Params() wants to reuse r12.  Since r12 is a non-volatile register, it must save the contents somewhere so it can restore the contents before the function exits.  All we have to do is locate that slot on the stack, and assuming that the stack has not been corrupted, we’ll have our prize.

    One technique for finding the slot is to start with the Child-SP value associated with the FunctionWith4Params() frame in the stack dump shown previously, which is 00000000`0012fdd0 in my build.  Using that value, let’s dump the stack content using the dps command:

    0:000> dps 00000000`0012fdd0 L10
    00000000`0012fdd0  00000001`00000001
    00000000`0012fdd8  00000001`40024040 example!_iob+0x30
    00000000`0012fde0  00000000`00000000
    00000000`0012fde8  00000001`40002f9e example!_getptd_noexit+0x76
    00000000`0012fdf0  00000000`00261310
    00000000`0012fdf8  00000001`40001a92 example!_unlock_file2+0x16
    00000000`0012fe00  00000000`00000001
    00000000`0012fe08  00000000`00004823
    00000000`0012fe10  00000000`000041bb
    00000000`0012fe18  00000000`00005af1
    00000000`0012fe20  00000000`00000000
    00000000`0012fe28  00000000`00000000
    00000000`0012fe30  00000000`00002cd6
    00000000`0012fe38  00000000`00000029
    00000000`0012fe40  00000000`00006952
    00000000`0012fe48  00000001`400158a0 example!FunctionWith5Params+0x20 [c:\temp\blog_entry\sample_code\example.cpp @ 34]

    I have highlighted the position that rsp points to when we enter FunctionWith4Params() in red.  Based on the prolog code shown for FunctionWith4Params() above, we can find the slot where our prize is stored.  I have highlighted it in green above and you can see the value on my machine is 0x29, which matches the value printf() sent to the console.  Additionally, I highlighted r14d in green in the assembly code for FunctionWith4Params() to indicate where the contents of edx (the second parameter) were copied to.  Since FunctionWith4Params() is virtually the top function on the stack (due to the fact that DebugBreak() takes no parameters), then r14d should also contain the value we are after.  Dumping the contents of r14 proves this as shown below:

    0:000> r r14
    r14=0000000000000029

    To sum up, when you are chasing register-passed parameter values down through a call graph, look for places where the value is copied into.  Specifically, if the value is copied into a non-volatile register, that can be a good thing.  If a downstream function wants to reuse that non-volatile register, it must first save the contents (usually on the stack) so it can restore it when it is done.  If you’re not that lucky, you may be able to trace a register it was copied into which has not been changed at the breakpoint.  Both conditions were shown above.

    Parameter Sleuthing -- Technique 2 (Up the Call Graph)

    The second technique I would like to demonstrate is very similar to the first technique except that we walk the stack/call-graph in the opposite direction as before, that is, up the call graph.  Unfortunately, none of these techniques are fool proof and guaranteed to bear fruit.  So, it’s nice to have multiple techniques to employ even though all of them may strike out.

    We know that when FunctionWith6Params() gets called, ecx contains the value we are after.  Therefore, if we look at the code for main(), maybe we can find the source from which the ecx register was filled prior to the function call.  Let’s have a look as the assembly code in main():

    0:000> u example!main example!main+0x5b
    example!main [c:\temp\blog_entry\sample_code\example.cpp @ 58]:
    00000001`400159b0 48895c2408      mov     qword ptr [rsp+8],rbx
    00000001`400159b5 48896c2410      mov     qword ptr [rsp+10h],rbp
    00000001`400159ba 4889742418      mov     qword ptr [rsp+18h],rsi
    00000001`400159bf 48897c2420      mov     qword ptr [rsp+20h],rdi
    00000001`400159c4 4154            push    r12
    00000001`400159c6 4883ec30        sub     rsp,30h
    00000001`400159ca e8bdbafeff      call    example!rand (00000001`4000148c)
    00000001`400159cf 448be0          mov     r12d,eax
    00000001`400159d2 e8b5bafeff      call    example!rand (00000001`4000148c)
    00000001`400159d7 8be8            mov     ebp,eax
    00000001`400159d9 e8aebafeff      call    example!rand (00000001`4000148c)
    00000001`400159de 8bf0            mov     esi,eax
    00000001`400159e0 e8a7bafeff      call    example!rand (00000001`4000148c)
    00000001`400159e5 8bf8            mov     edi,eax
    00000001`400159e7 e8a0bafeff      call    example!rand (00000001`4000148c)
    00000001`400159ec 8bd8            mov     ebx,eax
    00000001`400159ee e899bafeff      call    example!rand (00000001`4000148c)
    00000001`400159f3 448bcf          mov     r9d,edi
    00000001`400159f6 89442428        mov     dword ptr [rsp+28h],eax
    00000001`400159fa 448bc6          mov     r8d,esi
    00000001`400159fd 8bd5            mov     edx,ebp
    00000001`400159ff 418bcc          mov     ecx,r12d
    00000001`40015a02 895c2420        mov     dword ptr [rsp+20h],ebx
    00000001`40015a06 e8fab5feff      call    example!ILT+0(?FunctionWith6ParamsYAXHHHHHHZ) (00000001`40001005)

    We see that ecx was copied from the contents of r12d.  This is helpful since r12d is a non-volatile register, and if it is reused by a function further down the call stack, it must be preserved and that preservation usually means putting a copy on the stack.  It would have been nice if ecx were filled with a value from the stack, at which point we would be virtually done.  But in this case, we just need to start our journey back downwards again.

    We don’t have to look very far.  Let’s have another look at the prolog code for FunctionWith6Params():

    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
       41 00000001`400158e0 mov     qword ptr [rsp+8],rbx
       41 00000001`400158e5 mov     qword ptr [rsp+10h],rbp
       41 00000001`400158ea mov     qword ptr [rsp+18h],rsi
       41 00000001`400158ef push    rdi
       41 00000001`400158f0 push    r12
       41 00000001`400158f2 push    r13
       41 00000001`400158f4 sub     rsp,40h
       41 00000001`400158f8 mov     ebx,r9d
       41 00000001`400158fb mov     edi,r8d
       41 00000001`400158fe mov     esi,edx
       41 00000001`40015900 mov     r12d,ecx

    r12 is reused in FunctionWith6Params(), which means that our prize will be on the stack.  Let’s start by looking at the Child-SP for this frame which is at 00000000`0012fe80 by using the dps command:

    0:000> dps 00000000`0012fe80 L10
    00000000`0012fe80  00000000`00001649
    00000000`0012fe88  00000000`00005f90
    00000000`0012fe90  00000000`00000029
    00000000`0012fe98  00000000`00004823
    00000000`0012fea0  00000000`00006952
    00000000`0012fea8  00000001`00006784
    00000000`0012feb0  00000000`00004ae1
    00000000`0012feb8  00000001`00003d6c
    00000000`0012fec0  00000000`00000000
    00000000`0012fec8  00000000`00000029
    00000000`0012fed0  00000000`00006784
    00000000`0012fed8  00000001`4000128b example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 72]

    I have highlighted in red the slot rsp points to when we enter FunctionWith6Params().  At this point, it is a simple matter to walk the assembly code and find the slot where the value is stored.  I have highlighted it in green above.

    Parameter Sleuthing -- Technique 3 (Inspecting Dead Space)

    The final technique I would like to demonstrate involves a little more trickery and involves looking at “dead” or previously used slots on the stack that are not used by the current function call.  To demonstrate, let’s say that after the DebugBreak() is hit, we need to know what the contents of param4 that were passed to FunctionWith6Params().  Let’s have another look at the assembly that has executed for FunctionWith6Params() and this time, let’s follow r9d, the fourth parameter:

    0:000> u example!FunctionWith6Params example!FunctionWith6Params+0x97
    example!FunctionWith6Params [c:\temp\blog_entry\sample_code\example.cpp @ 41]:
    00000001`400158e0 mov     qword ptr [rsp+8],rbx
    00000001`400158e5 mov     qword ptr [rsp+10h],rbp
    00000001`400158ea mov     qword ptr [rsp+18h],rsi
    00000001`400158ef push    rdi
    00000001`400158f0 push    r12
    00000001`400158f2 push    r13
    00000001`400158f4 sub     rsp,40h
    00000001`400158f8 mov     ebx,r9d
    00000001`400158fb mov     edi,r8d
    00000001`400158fe mov     esi,edx
    00000001`40015900 mov     r12d,ecx
    00000001`40015903 call    example!rand (00000001`4000148c)
    00000001`40015908 movsxd  r13,eax
    00000001`4001590b call    example!rand (00000001`4000148c)
    00000001`40015910 lea     rdx,[example!`string'+0x68 (00000001`40020d40)]
    00000001`40015917 movsxd  rbp,eax
    00000001`4001591a mov     eax,dword ptr [rsp+88h]
    00000001`40015921 lea     rcx,[example!`string'+0x80 (00000001`40020d58)]
    00000001`40015928 mov     dword ptr [rsp+38h],eax
    00000001`4001592c mov     eax,dword ptr [rsp+80h]
    00000001`40015933 mov     r9d,esi
    00000001`40015936 mov     dword ptr [rsp+30h],eax
    00000001`4001593a mov     r8d,r12d
    00000001`4001593d mov     dword ptr [rsp+28h],ebx
    00000001`40015941 mov     dword ptr [rsp+20h],edi
    00000001`40015945 call    example!printf (00000001`400012bc)
    00000001`4001594a call    example!rand (00000001`4000148c)
    00000001`4001594f mov     edi,eax
    00000001`40015951 call    example!rand (00000001`4000148c)
    00000001`40015956 mov     esi,eax
    00000001`40015958 call    example!rand (00000001`4000148c)
    00000001`4001595d mov     ebx,eax
    00000001`4001595f call    example!rand (00000001`4000148c)
    00000001`40015964 mov     r9d,r12d
    00000001`40015967 mov     r8d,esi
    00000001`4001596a mov     edx,ebx
    00000001`4001596c mov     ecx,eax
    00000001`4001596e mov     dword ptr [rsp+20h],edi
    00000001`40015972 call    example!ILT+5(?FunctionWith5ParamsYAXHHHHHZ) (00000001`4000100a)

    Notice that r9d is first moved into ebx.  But also, notice that it copied the contents into a slot on the stack at rsp+0x28.  What is this slot?  It’s the sixth parameter to the following printf() call.  Remember that the compiler looks at all of the functions the code calls and finds the function with the maximum number of parameters and then allocates enough space for that function.  As the code prepares to call printf(), it is moving the value we are after into the sixth parameter slot in that reserved stack space.  But what use is this information?

    If you examine FunctionWith6Params(), you see that every function called after printf() takes less than six parameters.  Specifically, the call to FunctionWith5Params() only uses five of those slots and just leaves the remaining three with junk in them.  This junk is actually our treasure!  From examining the code, it’s guaranteed that nobody has overwritten the slot represented by rsp+28.

    To find this slot, let’s again start by getting the Child-SP value for the frame we’re talking about as shown below:

    0:000> kL
    Child-SP          RetAddr           Call Site
    00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    00000000`0012fee0 00000001`4000168b example!main+0x5b
    00000000`0012ff20 00000000`7733495d example!__tmainCRTStartup+0x15b
    00000000`0012ff60 00000000`77538791 kernel32!BaseThreadInitThunk+0xd
    00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    We can then take the highlighted value above and use the same offset in the code to find our value:

    0:000> dd 000000000012fe80+28 L1
    00000000`0012fea8  00006784

    As expected, the “dead” slot on the stack contains the value we are after.  You can compare the value to the output shown on the console to verify.

    A Non-volatile Register Shortcut

    Now that I have shown you the theory behind finding these elusive values passed around in registers, let me show you a shortcut that will make life a little bit easier.  The shortcut relies upon the /r option of the .frame command.  When using .frame /r, the debugger has the smarts to track non-volatile registers.  But as with any technique, always have multiple tools in your pocket in case you need to use all of them to verify a result.

    To demonstrate, let’s consider Technique 2 described previously where we look up the call graph and we want to know what r12 was prior to main() calling FunctionWith6Params().  Go ahead and re-launch the application in windbg and let it run until it hits the DebugBreak().  Now, let’s take a look at the stack including the frame numbers:

    0:000> knL
     # Child-SP          RetAddr           Call Site
    00 00000000`0012fdc8 00000001`40015816 ntdll!DbgBreakPoint
    01 00000000`0012fdd0 00000001`400158a0 example!FunctionWith4Params+0x66
    02 00000000`0012fe50 00000001`40015977 example!FunctionWith5Params+0x20
    03 00000000`0012fe80 00000001`40015a0b example!FunctionWith6Params+0x97
    04 00000000`0012fee0 00000001`4000168b example!main+0x5b
    05 00000000`0012ff20 00000000`7748495d example!__tmainCRTStartup+0x15b
    06 00000000`0012ff60 00000000`775b8791 kernel32!BaseThreadInitThunk+0xd
    07 00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

    Based on our previous analysis of the assembly in main(), we know that the first parameter to FunctionWith6Params() was also stored in the non-volatile register r12 in main() prior to calling FunctionWith6Params().  Now, check out what we get when we use the .frame /r command to set the current frame to 4.

    0:000> .frame /r 4
    04 00000000`0012fee0 00000001`4000168b example!main+0x5b [c:\temp\blog_entry\sample_code\example.cpp @ 70]
    rax=0000000000002ea6 rbx=0000000000004ae1 rcx=0000000000002ea6
    rdx=0000000000145460 rsi=00000000000018be rdi=0000000000006784
    rip=0000000140015a0b rsp=000000000012fee0 rbp=0000000000004823
     r8=000007fffffdc000  r9=0000000000001649 r10=0000000000000000
    r11=0000000000000246 r12=0000000000000029 r13=0000000000000000
    r14=0000000000000000 r15=0000000000000000
    iopl=0         nv up ei pl nz na pe nc
    cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
    example!main+0x5b:
    00000001`40015a0b 488b5c2440      mov     rbx,qword ptr [rsp+40h] ss:00000000`0012ff20=0000000000000000

    As you can see, .frame /r shows the register contents as they were in main() prior to calling FunctionWith6Params().  Beware!  You can only trust the non-volatile registers when using this command!  Be sure to check out the following link to see which registers are considered volatile: Register Usage for x64 64-Bit.

    .frame /r can spare you the time spent manually digging around on the stack to find saved volatile registers.  In my experiments, .frame /r even works where there is no symbol information available.  However, it never hurts to know how to do it manually in case you’re faced with a situation where .frame /r breaks down.

    Conclusion

    The x64 calling convention and the abundance of general purpose registers in the processor bring many opportunities for optimization to the table.  However, when all of those optimizations are in play, they can certainly make debugging difficult.  After giving a brief overview of the x64 calling convention, I demonstrated three techniques one can use to find parameter values to various functions in the call stack.  I also showed you a shortcut you can use to see non-volatile registers for a particular frame in the call stack.  I hope you find these techniques useful in your debugging adventures.  Additionally, I urge you to become more familiar with all of the nuances of the x64 calling convention.

     

  • Ntdebugging Blog

    Debug Fundamentals Exercise 4: The GAMEOVER exercise

    • 8 Comments

     

    We are back with another addition to the debugging fundamentals series here in 2009! Regardless of your debugging experience we hope you enjoy this one. Don’t worry too much if you can’t answer them all but give them your best shot.

     

    The problem:

     

    While debugging an application, a developer observes a crash and is puzzled. The developer saves a memory dump of the process using the command “.dump /ma dbgex4.dmp” and sends it to you for debug assistance.

     

    0:000> r

    eax=53454750 ebx=00000000 ecx=00000100 edx=000001b0 esi=001bfe20 edi=00ac36bc

    eip=47414d45 esp=001bfe00 ebp=4f564552 iopl=0         nv up ei pl zr na pe nc

    cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010246

    47414d45 ??              ???

     

    The attached zip, dbgex4.zip, includes three files. The program itself, the program’s symbols file and the saved memory dump file. (NOTE: You do not need to execute the program for the exercise however you may want to in order to solve the bonus’. You will need to rename the file dbgex4.ex_ to dbgex4.exe in order to run it).

     

    Using the accompanying files, answer the following questions:

     

    Part One – Debugging

     

    1.       What caused the access violation?

    2.       Examine the registers at the time of the crash.  Is there anything interesting about the contents?

    3.       How did the registers get into this state?

    4.       Find the offending data structure which caused this state to occur. What are its contents?

    5.       Are there security concerns with this access violation? Why?

    6.        Why is this class of crashes not seen in the wild much anymore?

    Part Two – Reverse Engineering

     

    Examine the functions main(), snap(), crack(), pop(), and boom().

    1.       Describe with a sentence or two what each one is doing.  (There is no need to comment on every assembly instruction or re-write the code in C here unless you really feel you need to.)

    Bonus:

    1.       If this access violation occurred while the program was running without a debugger present, would there be anything different about the crashing register state or the data structure which caused it? If so what is it and why? (HINT: If you would like to observe the crashing state like this, you can register windbg.exe to be the Just-In-Time debugger using the –I switch like so “windbg.exe -I”. When you run the dbgex4.exe program, it will crash and windbg.exe will launch automatically and attach to it.)

    2.       The functions from “Part Two – Reverse Engineering” perform operations on a set of data. During this manipulation some data is lost. Find this data and decode its “secret” message.

     

    Share this post :
Page 4 of 25 (242 items) «23456»