Postmortem Debugging with WinDBG or NTSD

I have mentioned several times before that using application verifier will help root cause and solve many bugs like for example memory bugs (leaks, heap corruptions, etc.), locking bugs, etc.  If in user mode (UM) you can just attach the debugger to your UM process and run your tests until in breaks in, or if in KM you would use a KD but the same thing applies.  

Let’s say that you have a heap corruption that is hard to track down in your UM process.  Normally you would do this:

1.       Isolate your code into a single process with a unique image name.

2.       Enable page heap on that image name using gflags.

3.       Start that process and attach a debugger (windbg)

4.       Reproduce the issue that causes the corruption and watch the debugger break in

5.       Then use the handy !heap –triage command to give you some more clues as to what is going on

Alternatively depending on what the memory problem is, in step 2, application verifier could also help.  It can be enable on your image with appverif.exe or gflags.exe.  If in KM, use driver verifier and KD. 

However with some bugs relating to race conditions, or memory corruptions, enabling these tools on your process or attaching the debugger its self could be enough to make it so that the issue doesn’t repro anymore.  That can be frustrating.

If directly debugging your process causes you to lose the repro, there are a few other techniques you can employ:

-          Tracing: adding WPP tracing to your code can be a great way to trouble shoot some issues with your code that are hard to capture with a debugger.  This is an especially good method for race conditions and deadlocks that don’t hit with a debugger.

-          KD: you can set up your machine for kernel debugging.  When you UM process has an unhandled exception, then the KD will break in.  KD is always a solid choice, but kernel debugging may be harder for some than UM debugging.  Also, some machines are hard to setup for KD like Ultrabooks where the debugable USB port may be internal to the chassis and soldered to the web cam, or it is an ARM tablet.

-          WER: Windows Error Reporting can be configured to capture dumps of your process when it crashes.  You can debug the dump after the fact.  Dump files are not as nice as debugging a live machine, but this could be a great option where your code is deployed to a lot of machines, and you want to see what happened on a machine where the bug repros.

-          Postmortem Debugging: you can configure Windows to launch and attach a debugger in response to a un handled exception.  This is called postmortem debugging.

All of these have their uses, but I will focus on postmortem debugging because it was the only way I could chase down a heap corruption that I have been trying to root cause for the past few days.

First off, you can use this link to read about it in detail if you like:

http://msdn.microsoft.com/en-us/library/windows/hardware/ff542967(v=vs.85).aspx

The basics are:

-          Simply type in an elevated command prompt “windbg –I” to make windbg the postmortem debugger.  This works great for processes in your login session. 

-          Use NTSD if you need to used named pipe debugging.  Type “ntsd –iae”.  You can use the –iaec “extra options” to add extra options, but it doesn’t work for –server like you need for name pipe debugging.  You need to manually edit the reg key  at \\HKEY_LOCAL_MACHINE\Software\Microsoft\Windows NT\CurrentVersion\AeDebug. 

GFlags.exe and Pageheap

I was tracking down a heap corruption today, and it occurred to me that I haven't mentioned how to enable pageheap.  For instance, when you use the handy "!heap -traige", if there was a heap corruption, sometimes it will tell to try the repro again with pageheap enabled.  How do you do that?

There are actually several ways to enable pageheap, but I will only talk about one, modifying the global flags using gflags.exe.  It should get installed when you install windbg.

Basically for a user mode (UM) process, you go to the image file tab, and type in the name of your exe.  If you run in a svchost.exe, then you should probably break out your service to a uniquely named servicehost.exe.  I use myhost.exe normally for debugging a service.  After that, check "Enable page heap."

Next, you need to run the code in question under  the debugger, and then you reproduce the heap corruption.  Normally the debugger will break in This time you will be able to get a lot more useful information out of !heap and !analyze.

See the OS Version in WinDBG

I seem to forget this command every so often, so it is ripe for a post.  Often I will be debugging a remote KD from some other team, and I want to know what version of the OS I am debugging.  The command for this is vertarget.  Super obvious.  Obviously the next most obvious command would be version, which is for the version of the debugger, and ver which is nothing.

Here is some sample output of vertarget:

0:005> vertarget
Windows 8 Version 9200 MP (4 procs) Free x64 <= looks like the output of GetVersionEx which lies after 8, and always says it Windows 8.
Product: WinNt, suite: SingleUserTS
kernel32.dll version: 6.3.9418.0 (winmain.130530-1753) <= This looks the actual version you would get fro m RtlGetVersion
Machine Name: "bob"
Debug session time: Fri May 31 19:12:24.000 2013 (UTC - 7:00)
System Uptime: 0 days 1:03:12.334
Process Uptime: 0 days 0:16:35.000
  Kernel time: 0 days 0:00:00.000
  User time: 0 days 0:00:00.000

This is what it looks like from a KD:
0: kd> vertarget
Windows 8 Kernel Version 9658 MP (4 procs) Free x64
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 9658.0.amd64fre.winmain.131120-1618
Machine Name: "bobby-brown"
Kernel base = 0xfffff801`d3e15000 PsLoadedModuleList = 0xfffff801`d40dfb90
Debug session time: Fri Nov 22 14:28:29.746 2013 (UTC - 8:00)
System Uptime: 0 days 0:45:58.445

WinDBG: dt vs ??

dt

The dt command stands for display type.

usage:

dt var

dt address

??

The ?? command is for evaluating a C++ expression.  You can use it like dt, but you can use it to do even more.  I personally like to just use it most of the time because C are more accessible to me often than trying to remember which switches I need to use with dt.

usage:

?? sizeof(var)

?? this

?? this->m_member_obj

?? array[25].member_ptr->val

?? g_some_global

Checking an Event's Signaled State in KM w/ WinDBG

I've talked about debugging events in the past in UM in simple terms.  !handle works great, and although is use is slightly different in UM vs KM it provides a lot of good information, but lets say you are in KD and want to know if your event is signaled or not.  !handle will not tell you that.  This is how you do it.  Note: you need to have a KD to look at the kernel's objects.

1. Find the index of handle


1: kd> dt g_hMyEvent
my_bin!g_hMyEvent
0x00001218
Void

2. Use !handle to get the address of the event object.

1: kd> !handle 0x00001218 f -1 Event

Searching for handles of type Event

PROCESS 845f4b40  SessionId: 0  Cid: 040c    Peb: 7fbb4000  ParentCid: 023c
    DirBase: 7ffea200  ObjectTable: a194d280  HandleCount: 1071.
    Image: svchost.exe

Handle table at a194d280 with 1071 entries in use

1218: Object: aa934288  GrantedAccess: 001f0003 Entry: bb591430
Object: aa934288  Type: (845692b8) Event
    ObjectHeader: aa934270 (new version)
        HandleCount: 1  PointerCount: 62

3. Cast that pointer to the dispatch header it is

1: kd> ?? (PDISPATCHER_HEADER)0xaa934288

PDISPATCHER_HEADER 0xaa934288

   +0x000 Type             : 0 ''

   +0x001 TimerControlFlags : 0 ''

   +0x001 Absolute         : 0y0

   +0x001 Wake             : 0y0

   +0x001 EncodedTolerableDelay : 0y000000 (0)

   +0x001 Abandoned        : 0 ''

   +0x001 Signalling       : 0 ''

   +0x002 ThreadControlFlags : 0x4 ''

   +0x002 CycleProfiling   : 0y0

   +0x002 CounterProfiling : 0y0

   +0x002 GroupScheduling  : 0y1

   +0x002 AffinitySet      : 0y0

   +0x002 Reserved         : 0y0000

   +0x002 Hand             : 0x4 ''

   +0x002 Size             : 0x4 ''

   +0x003 TimerMiscFlags   : 0 ''

   +0x003 Index            : 0y0

   +0x003 Processor        : 0y00000 (0)

   +0x003 Inserted         : 0y0

   +0x003 Expired          : 0y0

   +0x003 DebugActive      : 0 ''

   +0x003 DpcActive        : 0 ''

   +0x000 Lock             : 0n262144

   +0x000 LockNV           : 0n262144

   +0x004 SignalState      : 0n1

   +0x008 WaitListHead     : _LIST_ENTRY [ 0xaa934290 - 0xaa934290 ]

There you go, you can see this event is in a signaled state.

By the way, the member Type 0 means event notification.  Other common values:

    EventNotificationObject = 0,
    EventSynchronizationObject = 1,
    MutantObject = 2,
    ProcessObject = 3,
    QueueObject = 4,
    SemaphoreObject = 5,
    ThreadObject = 6,

Setting FILETIME Timeout for SetThreadpoolWait

Using Window's new (since Vista) Threadpool is great.  You can read up on it here.  If you want some sample code on usage patterns, message me, and I can do a post on it later.

The threadpool has a generic wait on an handle (eg. event, process, etc.) mechanism.  It even has a timeout so say you want to wait either for an event or a timeout, but the timeout is in FILETIME format.  How do you convert a specified amount say in ms of time into a FILETIME?

HRESULT DoWaitWithTimeout(
    __in DWORD Timeout) // in ms
{
    HRESULT hr = S_OK;
    PMY_CONTEXT pContext = NULL;
    FILETIME timeout = {0};

    pContext = (PMY_CONTEXT)my_alloc(sizeof(MY_CONTEXT));

    if (!pContext) {
        hr = E_OUTOFMEMORY;
        goto Exit;
    }

    ZeroMemory(pContext, sizeof(MY_CONTEXT));
    pContext->hEvent = CreateEvent(NULL, TRUE, FALSE, NULL);

    if (!pContext->hEvent) {
        hr = HRESULT_FROM_WIN32(GetLastError());
        goto Exit;
    }

    pContext->hWait = CreateThreadpoolWait(
            MyWaitCallback,
            pContext,
            NULL);

    if (!pContext->hWait) {
        hr = HRESULT_FROM_WIN32(GetLastError());
        goto Exit;
    }

    if (Timeout) {
        ULARGE_INTEGER ulTimeout = {0};

        // Timeout in ms, FILETIME is in 100 ns increments
        ulTimeout.QuadPart = Timeout * -10000; 
        timeout.dwHighDateTime = ulTimeout.HighPart;
        timeout.dwLowDateTime = ulTimeout.LowPart;
    }
  
    SetThreadpoolWait(
            pContext->hWait,
            pContext->hEvent,
            &timeout);

// ...

How to Debug a Deadlock in KD & WinDBG

In my last post, I was looking at some threads in KD and noticed there was a deadlock.  I will quickly go through the analysis of that particular deadlock.  You can review that post here.

As a quick review, I dumped the stacks of the running threads in the process.  The one that we knew was hung, was waiting to be notified.  Then the problem thread that was supposed to notify was hung waiting on an object.  Inspecting the stack led us to frame 9.  Looking at the source:

DWORD WINAPI CNotificationQueue::ThreadProc( void * pv )

{

...

        while ( 0 == s_lThreadShuttingDown )

        {

            EnterCriticalSection( &s_cs );

            poNotification = RemoveHead();

            if ( poNotification )

We can see this code is taking a lock on s_cs, a global.  

0: kd> ?? CNotificationQueue::s_cs

struct _RTL_CRITICAL_SECTION

   +0x000 DebugInfo        : 0x026acca0 _RTL_CRITICAL_SECTION_DEBUG

   +0x004 LockCount        : 0n-1

   +0x008 RecursionCount   : 0n0

   +0x00c OwningThread     : (null)

   +0x010 LockSemaphore    : 0x00000558 Void

   +0x014 SpinCount        : 0x20007d0

0: kd> !cs 0x026acca0

-----------------------------------------

Critical section   = 0x026acca0 (+0x26ACCA0)

Uninitialized or deleted.

LOCKED

LockCount          = 0xE4C5EB20

WaiterWoken        = Yes

OwningThread       = 0x00857380

RecursionCount     = 0x2658C70

LockSemaphore      = 0x0

SpinCount          = 0x00000031

0: kd>

So, this code is taking a lock on an invalid critical section, and hangs.  At this point if this bug reproduces, it would be good to run this again with Application Verifier enabled on the faulty code.