Archive for July, 2007

Listening to Computer Memory

Sunday, July 29th, 2007

An alternative to converting memory dumps to sound files is to save a memory range to a binary file and then convert it to a wave file. The latter is better for complete memory dumps which can be several Gb in size.

To save a memory range to a file use WinDbg .writemem command:

.writemem d2w-range.bin 00400000 00433000

or

.writemem d2w-range.bin 00400000 L200

I wrote a WinDbg script that saves a specified memory range and then calls a shell script which automatically converts saved binary file to a wave file and then runs whatever sound program is registered for .wav extension. On many systems it is Microsoft Media Player unless you installed any other third-party player.

The WinDbg script code (memsounds.txt):

.writemem d2w-range.bin ${$arg1} ${$arg2}
.if (${/d:$arg5})
{
  .shell -i- memsounds.cmd d2w-range ${$arg3} ${$arg4} ${$arg5}
}
.elsif (${/d:$arg4})
{
  .shell -i- memsounds.cmd d2w-range ${$arg3} ${$arg4}
}
.elsif (${/d:$arg3})
{
  .shell -i- memsounds.cmd d2w-range ${$arg3}
}
.else
{
  .shell -i- memsounds.cmd d2w-range
}

The shell script (memsounds.cmd):

dump2wave %1.bin %1.wav %2 %3 %4
%1.wav

Because WinDbg installation folder is assumed to be the default directory for both scripts and Dump2Wave.exe they should be copied to the same folder where windbg.exe is located. On my system it is

C:\Program Files\Debugging Tools for Windows

Both scripts are included in Dump2Wave package available for free download:

Dump2Wave package

To call the script from WinDbg use the following command:

$$>a< memsounds.txt Range [Freq] [Bits] [Channels]

where Range can be in Address1 Address2 or Address Lxxx format, Freq can be 44100, 22050, 11025 or 8000, Bits can be 8 or 16, Channels can be 1 or 2. By default it is 44100, 16, 2.

If you have a live debugging session or loaded a crash dump you can listen to a memory range immediately. For example, the range of memory from 00400000 to 00433000 interpreted as 44.1KHz 16bit stereo:

0:000> $$>a< memsounds.txt 00400000 00433000
Writing 33001 bytes...

C:\Program Files\Debugging Tools for Windows>dump2wave d2w-range.bin d2w-range.wav

Dump2Wave version 1.2.1
Written by Dmitry Vostokov, 2006

d2w-range.wav
d2w-range.bin
        1 file(s) copied.

C:\Program Files\Debugging Tools for Windows>d2w-range.wav
.shell: Process exited
0:000>

or the same range interpreted as 8KHz 8bit mono:

0:000> $$>a< memsounds.txt 00400000 00433000 8000 8 1
Writing 33001 bytes...

C:\Program Files\Debugging Tools for Windows>dump2wave d2w-range.bin d2w-range.wav 8000 8 1

Dump2Wave version 1.2.1
Written by Dmitry Vostokov, 2006

d2w-range.wav
d2w-range.bin
        1 file(s) copied.

C:\Program Files\Debugging Tools for Windows>d2w-range.wav
.shell: Process exited
0:000>

The script starts Windows Media Player on my system and I only need to push the play button to start listening.

Enjoy :-)

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 9c)

Saturday, July 28th, 2007

This is another variant of Deadlock pattern when we have mixed synchronization objects, for example, events and critical sections. An event may be used to signal the availability of some work item for processing it, the fact that the queue is not empty and a critical section may be used to protect some shared data. 

The typical deadlock scenario here is when one thread resets an event by calling WaitForSingleObject and tries to acquire a critical section. In the mean time the second thread has already acquired that critical section and now is waiting for the event to be set:

Thread A     |  Thread B
..           |  ..
reset Event  |  ..
..           |  acquire CS
wait for CS  |  ..
             |  wait for Event

The classical fix to this bug is to acquire the critical section and wait for the event in the same order in both threads.

In our example crash dump we can easily identify the second thread that acquied the critical section and is waiting for the event 0×480:

0:000> !locks

CritSec ntdll!LdrpLoaderLock+0 at 7c889d94
WaiterWoken        No
LockCount          9
RecursionCount     1
OwningThread       2038
EntryCount         0
ContentionCount    164
*** Locked

  13  Id: 590.2038 Suspend: 1 Teb: 7ffaa000 Unfrozen
ChildEBP RetAddr  Args to Child
0483fd5c 7c822124 77e6bad8 00000480 00000000 ntdll!KiFastSystemCallRet
0483fd60 77e6bad8 00000480 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0483fdd0 77e6ba42 00000480 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
0483fde4 776cfb30 00000480 ffffffff 777904f8 kernel32!WaitForSingleObject+0×12
0483fe00 776adfaa 00000480 00000000 00000080 ole32!CDllHost::ClientCleanupFinish+0×2a
0483fe2c 776adf1a 00000000 0483fe7c 77790828 ole32!DllHostProcessUninitialize+0×80
0483fe4c 776b063f 00000000 00000000 0c9ecee0 ole32!ApartmentUninitialize+0xf8
0483fe64 776b06e3 0483fe7c 00000000 00000001 ole32!wCoUninitialize+0×48
0483fe80 776e43f5 00000001 77670000 776afef0 ole32!CoUninitialize+0×65
0483fe8c 776afef0 0483feb4 776b5cb8 77670000 ole32!DoThreadSpecificCleanup+0×63
0483fe94 776b5cb8 77670000 00000003 00000000 ole32!ThreadNotification+0×37
0483feb4 776b5c1b 77670000 00000003 00000000 ole32!DllMain+0×176
0483fed4 7c82257a 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0×52
0483fef4 7c83c195 776b5bd3 77670000 00000003 ntdll!LdrpCallInitRoutine+0×14
0483ffa8 77e661d6 00000000 00000000 0483ffec ntdll!LdrShutdownThread+0xd2
0483ffb8 77e66090 00000000 00000000 00000000 kernel32!ExitThread+0×2f
0483ffec 00000000 77c5de6d 0ab24f68 00000000 kernel32!BaseThreadStart+0×39

0:000> !handle 480 ff
Handle 00000480
  Type          Event
  Attributes    0
  GrantedAccess 0×1f0003:
         Delete,ReadControl,WriteDac,WriteOwner,Synch
         QueryState,ModifyState
  HandleCount   2
  PointerCount  4
  Name          <none>
  No object specific information available

It is difficult to find the first thread, the one which has reset the event and is waiting for the critical section. In our dump we have 9 such threads from !locks command output:

LockCount          9

Event as a synchronization primitive doesn’t have an owner. Despite this we can try to find 0×480 and WaitForSingleObject address near on some other thread raw stack if that information wasn’t overwritten. Let’s do a memory search:

0:000> s -d 0 L4000000 00000480
000726ec 00000480 00000022 000004a4 00000056
008512a0 00000480 00000480 00000000 00000000
008512a4 00000480 00000000 00000000 01014220
0085ab68 00000480 00000480 00000092 00000000
0085ab6c 00000480 00000092 00000000 01014234
00eb12a0 00000480 00000480 00000000 00000000
00eb12a4 00000480 00000000 00000000 0101e614
00ebeb68 00000480 00000480 00000323 00000000
00ebeb6c 00000480 00000323 00000000 0101e644
03ffb4fc 00000480 d772c13b ce753966 00fa840f
040212a0 00000480 00000480 00000000 00000000
040212a4 00000480 00000000 00000000 01063afc
0402ab68 00000480 00000480 00000fb6 00000000
0402ab6c 00000480 00000fb6 00000000 01063b5c
041312a0 00000480 00000480 00000000 00000000
041312a4 00000480 00000000 00000000 01065b28
0413eb68 00000480 00000480 00001007 00000000
0413eb6c 00000480 00001007 00000000 01065b7c
043412a0 00000480 00000480 00000000 00000000
043412a4 00000480 00000000 00000000 01066b44
0434ab68 00000480 00000480 00001033 00000000
0434ab6c 00000480 00001033 00000000 01066b9c
0483fd68 00000480 00000000 00000000 00000000
0483fdd8 00000480 ffffffff 00000000 0483fe00
0483fdec 00000480 ffffffff 777904f8 77790738
0483fe08 00000480 00000000 00000080 776b0070
0483fe20 00000480 00000000 00000000 0483fe4c

05296f58 00000480 ffffffff ffffffff ffffffff
05297eb0 00000480 00000494 000004a4 000004c0
0557cf9c 00000480 00000000 00000000 00000000
05580adc 00000480 00000000 00000000 00000000
0558715c 00000480 00000000 00000000 00000000
0558d3cc 00000480 00000000 00000000 00000000
0559363c 00000480 00000000 00000000 00000000
0559ee0c 00000480 00000000 00000000 00000000
055a507c 00000480 00000000 00000000 00000000
056768ec 00000480 00000000 00000000 00000000
0568ef14 00000480 00000000 00000000 00000000
0581ff88 00000480 07ca7ee0 0581ff98 776cf2a3
05ed1260 00000480 00000480 00000000 00000000
05ed1264 00000480 00000000 00000000 01276efc
05ed8b68 00000480 00000480 00005c18 00000000
05ed8b6c 00000480 00005c18 00000000 01276f74
08f112a0 00000480 00000480 00000000 00000000
08f112a4 00000480 00000000 00000000 00000000
08f1ab68 00000480 00000480 00007732 00000000
08f1ab6c 00000480 00007732 00000000 01352db0

In blue color I highlighted the thread #13 raw stack occurrences and in red color I highlighted memory locations that belong to another thread raw stack. In fact, these are the only memory locations from search results that make any sense from code perspective. The only meaningful stack traces can be found in memory locations highlighted in blue and red above.

This can be seen if we feed search results to WinDbg dds command (not all output is shown for clarity):

0:000> .foreach (place { s-[1]d 0 L4000000 00000480 }) { dds place -30; .printf "\n" }
000726bc  00000390
000726c0  00000022
000726c4  000003b4
000726c8  00000056
000726cc  00000004
000726d0  6dc3f6fd
000726d4  0000040c
000726d8  0000001e
000726dc  0000042c
000726e0  00000052
000726e4  00000004
000726e8  eacb0f6d
000726ec  00000480
000726f0  00000022
000726f4  000004a4
000726f8  00000056
000726fc  00000004
00072700  62b796d2
00072704  000004fc
00072708  0000001e
0007270c  0000051c
00072710  00000052
00072714  00000004
00072718  2a615cff
0007271c  00000570
00072720  00000024
00072724  00000598
00072728  00000058
0007272c  00000004
00072730  51913e59
00072734  000005f0
00072738  00000016
...
...
...
0568eee4  05680008 xpsp2res+0x1b0008
0568eee8  01200000
0568eeec  00001010
0568eef0  00200001
0568eef4  00000468
0568eef8  00000121
0568eefc  00000000
0568ef00  00000028
0568ef04  00000030
0568ef08  00000060
0568ef0c  00040001
0568ef10  00000000
0568ef14  00000480
0568ef18  00000000
0568ef1c  00000000
0568ef20  00000000
0568ef24  00000000
0568ef28  00000000
0568ef2c  00800000
0568ef30  00008000
0568ef34  00808000
0568ef38  00000080
0568ef3c  00800080
0568ef40  00008080
0568ef44  00808080
0568ef48  00c0c0c0
0568ef4c  00ff0000
0568ef50  0000ff00
0568ef54  00ffff00
0568ef58  000000ff
0568ef5c  00ff00ff
0568ef60  0000ffff

0581ff58  0581ff70
0581ff5c  776b063f ole32!wCoUninitialize+0x48
0581ff60  00000001
0581ff64  00007530
0581ff68  77790438 ole32!gATHost
0581ff6c  00000000
0581ff70  0581ff90
0581ff74  776cf370 ole32!CDllHost::WorkerThread+0xdd
0581ff78  0581ff8c
0581ff7c  00000001
0581ff80  77e6ba50 kernel32!WaitForSingleObjectEx
0581ff84  0657cfe8
0581ff88  00000480

0581ff8c  07ca7ee0
0581ff90  0581ff98
0581ff94  776cf2a3 ole32!DLLHostThreadEntry+0xd
0581ff98  0581ffb8
0581ff9c  776b2307 ole32!CRpcThread::WorkerLoop+0×1e
0581ffa0  77790438 ole32!gATHost
0581ffa4  00000000
0581ffa8  0657cfe8
0581ffac  77670000 ole32!_imp__InstallApplication <PERF> (ole32+0×0)
0581ffb0  776b2374 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×20
0581ffb4  00000000
0581ffb8  0581ffec
0581ffbc  77e6608b kernel32!BaseThreadStart+0×34
0581ffc0  0657cfe8
0581ffc4  00000000
0581ffc8  00000000
0581ffcc  0657cfe8
0581ffd0  3cfb5963
0581ffd4  0581ffc4

05ed1230  0101f070
05ed1234  05ed1274
05ed1238  05ed1174
05ed123c  05ed0000
05ed1240  05ed1280
05ed1244  00000000
05ed1248  00000000
05ed124c  00000000
05ed1250  05ed8b80
05ed1254  05ed8000
05ed1258  00002000
05ed125c  00001000
05ed1260  00000480
05ed1264  00000480
05ed1268  00000000
05ed126c  00000000
05ed1270  01276efc
05ed1274  05ed12b4
05ed1278  05ed1234
05ed127c  05ed0000
05ed1280  05ed2d00
05ed1284  05ed1240
05ed1288  05ed1400
05ed128c  00000000
05ed1290  05edade0
05ed1294  05eda000
05ed1298  00002000
05ed129c  00001000
05ed12a0  00000220
05ed12a4  00000220
05ed12a8  00000000
05ed12ac  00000000
...
...
...
08f1ab3c  00000000
08f1ab40  00000000
08f1ab44  00000000
08f1ab48  00000000
08f1ab4c  00000000
08f1ab50  00000000
08f1ab54  00000000
08f1ab58  00000000
08f1ab5c  00000000
08f1ab60  abcdbbbb
08f1ab64  08f11000
08f1ab68  00000480
08f1ab6c  00000480
08f1ab70  00007732
08f1ab74  00000000
08f1ab78  01352db0
08f1ab7c  dcbabbbb
08f1ab80  ffffffff
08f1ab84  c0c00ac1
08f1ab88  00000000
08f1ab8c  c0c0c0c0
08f1ab90  c0c0c0c0
08f1ab94  c0c0c0c0
08f1ab98  c0c0c0c0
08f1ab9c  c0c0c0c0
08f1aba0  c0c0c0c0
08f1aba4  ffffffff
08f1aba8  c0c00ac1
08f1abac  00000000
08f1abb0  c0c0c0c0
08f1abb4  c0c0c0c0
08f1abb8  c0c0c0c0

We see that address 0581ff88 is the most meaningful and it also has WaitForSingleObjectEx nearby. This address belongs to the raw stack of the following thread #16:

  16  Id: 590.1a00 Suspend: 1 Teb: 7ffa9000 Unfrozen
ChildEBP RetAddr
0581fc98 7c822124 ntdll!KiFastSystemCallRet
0581fc9c 7c83970f ntdll!NtWaitForSingleObject+0xc
0581fcd8 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19c
0581fcf8 7c83a023 ntdll!RtlEnterCriticalSection+0xa8
0581fe00 77e67bcd ntdll!LdrUnloadDll+0x35
0581fe14 776b46fb kernel32!FreeLibrary+0x41
0581fe20 776b470f ole32!CClassCache::CDllPathEntry::CFinishObject::Finish+0x2f
0581fe34 776b44a0 ole32!CClassCache::CFinishComposite::Finish+0x1d
0581ff0c 776b0bfd ole32!CClassCache::CleanUpDllsForApartment+0x1d0
0581ff38 776b0b1f ole32!FinishShutdown+0xd7
0581ff58 776b063f ole32!ApartmentUninitialize+0x94
0581ff70 776cf370 ole32!wCoUninitialize+0x48
0581ff90 776cf2a3 ole32!CDllHost::WorkerThread+0xdd
0581ff98 776b2307 ole32!DLLHostThreadEntry+0xd
0581ffac 776b2374 ole32!CRpcThread::WorkerLoop+0×1e
0581ffb8 77e6608b ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×20
0581ffec 00000000 kernel32!BaseThreadStart+0×34

And if we disassemble ole32!CRpcThread::WorkerLoop function which is found below WaitForSingleObjectEx on both stack trace and raw stack data from search results we would see that the former function calls the latter function indeed:

0:000> uf ole32!CRpcThread::WorkerLoop
ole32!CRpcThread::WorkerLoop:
776b22e9 mov     edi,edi
776b22eb push    esi
776b22ec mov     esi,ecx
776b22ee cmp     dword ptr [esi+4],0
776b22f2 jne     ole32!CRpcThread::WorkerLoop+0x67 (776b234d)

ole32!CRpcThread::WorkerLoop+0xb:
776b22f4 push    ebx
776b22f5 push    edi
776b22f6 mov     edi,dword ptr [ole32!_imp__WaitForSingleObjectEx (77671304)]
776b22fc mov     ebx,7530h

ole32!CRpcThread::WorkerLoop+0x18:
776b2301 push    dword ptr [esi+0Ch]
776b2304 call    dword ptr [esi+8]
776b2307 call    dword ptr [ole32!_imp__GetCurrentThread (7767130c)]
776b230d push    eax
776b230e call    dword ptr [ole32!_imp__RtlCheckForOrphanedCriticalSections (77671564)]
776b2314 xor     eax,eax
776b2316 cmp     dword ptr [esi],eax
776b2318 mov     dword ptr [esi+8],eax
776b231b mov     dword ptr [esi+0Ch],eax
776b231e je      ole32!CRpcThread::WorkerLoop+0x65 (776b234b)

ole32!CRpcThread::WorkerLoop+0x37:
776b2320 push    esi
776b2321 mov     ecx,offset ole32!gRpcThreadCache (7778fc28)
776b2326 call    ole32!CRpcThreadCache::AddToFreeList (776de78d)

ole32!CRpcThread::WorkerLoop+0x55:
776b232b push    0
776b232d push    ebx
776b232e push    dword ptr [esi]
776b2330 call    edi

776b2332 test    eax,eax
776b2334 je      ole32!CRpcThread::WorkerLoop+0×60 (776cf3be)

ole32!CRpcThread::WorkerLoop+0x44:
776b233a push    esi
776b233b mov     ecx,offset ole32!gRpcThreadCache (7778fc28)
776b2340 call    ole32!CRpcThreadCache::RemoveFromFreeList (776e42de)
776b2345 cmp     dword ptr [esi+4],0
776b2349 je      ole32!CRpcThread::WorkerLoop+0x55 (776b232b)

ole32!CRpcThread::WorkerLoop+0x65:
776b234b pop     edi
776b234c pop     ebx

ole32!CRpcThread::WorkerLoop+0x67:
776b234d pop     esi
776b234e ret

ole32!CRpcThread::WorkerLoop+0x60:
776cf3be cmp     dword ptr [esi+4],eax
776cf3c1 je      ole32!CRpcThread::WorkerLoop+0x18 (776b2301)

ole32!CRpcThread::WorkerLoop+0x69:
776cf3c7 jmp     ole32!CRpcThread::WorkerLoop+0x65 (776b234b)

Therefore we have possibly identified the thread #16 that resets the event by calling WaitForSingleObjectEx and tries to acquire the critical section. We also know the second thread #13 that has already acquired that critical section and now is waiting for the event to be signaled.

- Dmitry Vostokov @ DumpAnalysis.org -

Reading Windows-based Code (Part 3)

Friday, July 27th, 2007

The HTML version of the presentation is located here:

Reading Windows-based Code (Part 3)

The 4th part coming next week will be about Windows specific types and will describe in detail the structure of a typical Windows GUI program. 

- Dmitry Vostokov @ DumpAnalysis.org -

Reconstructing Stack Trace Manually

Wednesday, July 25th, 2007

This is a small case study to complement Incorrect Stack Trace pattern and show how to reconstruct stack trace manually based on an example with complete source code.

I created a small working multithreaded program:

#include "stdafx.h"
#include <stdio.h>
#include <process.h>

typedef void (*REQ_JUMP)();
typedef void (*REQ_RETURN)();

const char str[] = "\0\0\0\0\0\0\0";

bool loop = true;

void return_func()
{
  puts("Return Func");
  loop = false;
  _endthread();
}

void jump_func()
{
  puts("Jump Func");
}

void internal_func_2(void *param_jump,void *param_return)
{
  REQ_JUMP f_jmp = (REQ_JUMP)param_jump;
  REQ_RETURN f_ret = (REQ_RETURN)param_return;

  puts("Internal Func 2");
  // Uncomment memcpy to crash the program
  // Overwrite f_jmp and f_ret with NULL
  // memcpy(&f_ret, str, sizeof(str));
  __asm
  {
     push f_ret;
     mov  eax, f_jmp
     mov  ebp, 0 // use ebp as a general purpose register
     jmp  eax
  }
}

void internal_func_1(void *param)
{
  puts("Internal Func 1");
  internal_func_2(param, &return_func);
}

void thread_request(void *param)
{
  puts("Request");
  internal_func_1(param);
}

int _tmain(int argc, _TCHAR* argv[])
{
  _beginthread(thread_request, 0, (void *)jump_func);
  while (loop);
  return 0;
}

For it I had to disable optimizations in Visual C++ compiler otherwise most of the code would have been eliminated because the program is very small and easy for code optimizer. If we run the program it displays the following output:

Request
Internal Func 1
Internal Func 2
Jump Func
Return Func

internal_func_2 gets two parameters: the function address to jump and the function address to call upon the return. The latter sets loop variable to false in order to break infinite main thread loop and calls _endthread. Why is that complexity in so small sample? I wanted to simulate FPO optimization in an inner function call and also gain control over a return address. This is why I set EBP to zero before jumping and pushed the custom return address which I can change any time. If I used the call instruction then the processor would have determined the return address as the next instruction address.

The code also copies two internal_func_2 parameters into local variables f_jmp and f_ret because the commented memcpy call is crafted to overwrite them with zeroes and do not touch the saved EBP, return address and function arguments. This is all to make stack trace incorrect but at the same time make manual stack reconstruction as easy as possible in this example.

Let’s suppose that memcpy call is a bug that overwrites local variables. Then we have a crash obviously because EAX is zero and jump to zero address will cause access violation. EBP is also 0 because we assigned 0 to it explicitly. Let’s pretend that we wanted to pass some constant via EBP and it is zero.

What we have now:

EBP is 0
EIP is 0
the return address is 0

As you might have expected already when you load a crash dump WinDbg is utterly confused because it has no clue on how to reconstruct the stack trace:

This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(bd0.ec8): Access violation - code c0000005 (first/second chance not available)
eax=00000000 ebx=00595620 ecx=00000002 edx=00000000 esi=00000000 edi=00000000
eip=00000000 esp=0069ff54 ebp=00000000 iopl=0 nv up ei pl nz ac po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010212
00000000 ??              ???

0:001> kv
ChildEBP RetAddr  Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
0069ff50 00000000 00000000 00000000 0069ff70 0×0

Fortunately ESP is not zero so we can look at raw stack:

0:001> dds esp
0069ff54  00000000
0069ff58  00000000
0069ff5c  00000000
0069ff60  0069ff70
0069ff64  0040187f WrongIP!internal_func_1+0x1f
0069ff68  00401830 WrongIP!jump_func
0069ff6c  00401840 WrongIP!return_func
0069ff70  0069ff7c
0069ff74  0040189c WrongIP!thread_request+0xc
0069ff78  00401830 WrongIP!jump_func
0069ff7c  0069ffb4
0069ff80  78132848 msvcr80!_endthread+0x4b
0069ff84  00401830 WrongIP!jump_func
0069ff88  aa75565b
0069ff8c  00000000
0069ff90  00000000
0069ff94  00595620
0069ff98  c0000005
0069ff9c  0069ff88
0069ffa0  0069fb34
0069ffa4  0069ffdc
0069ffa8  78138cd9 msvcr80!_except_handler4
0069ffac  d207e277
0069ffb0  00000000
0069ffb4  0069ffec
0069ffb8  781328c8 msvcr80!_endthread+0xcb
0069ffbc  7d4dfe21 kernel32!BaseThreadStart+0x34
0069ffc0  00595620
0069ffc4  00000000
0069ffc8  00000000
0069ffcc  00595620
0069ffd0  c0000005

Here we can start searching for the following pairs:

EBP:         PreviousEBP
             Function return address



PreviousEBP: PrePreviousEBP
             Function return address


for example:

0:001> dds esp
0069ff54 00000000
0069ff58 00000000
0069ff5c 00000000
0069ff60 0069ff70
0069ff64 0040187f WrongIP!internal_func_1+0×1f
0069ff68 00401830 WrongIP!jump_func
0069ff6c 00401840 WrongIP!return_func
0069ff70 0069ff7c
0069ff74 0040189c WrongIP!thread_request+0xc
0069ff78 00401830 WrongIP!jump_func
0069ff7c 0069ffb4

This is based on the fact that a function call saves its return address and the standard function prolog saves the previous EBP value and sets ESP to point to it.

push ebp
mov ebp, esp

Therefore our stack looks like this:

0:001> dds esp
0069ff54 00000000
0069ff58 00000000
0069ff5c 00000000
0069ff60 0069ff70
0069ff64 0040187f WrongIP!internal_func_1+0×1f
0069ff68 00401830 WrongIP!jump_func
0069ff6c 00401840 WrongIP!return_func
0069ff70 0069ff7c
0069ff74 0040189c WrongIP!thread_request+0xc
0069ff78 00401830 WrongIP!jump_func
0069ff7c 0069ffb4
0069ff80 78132848 msvcr80!_endthread+0×4b
0069ff84 00401830 WrongIP!jump_func
0069ff88 aa75565b
0069ff8c 00000000
0069ff90 00000000
0069ff94 00595620
0069ff98 c0000005
0069ff9c 0069ff88
0069ffa0 0069fb34
0069ffa4 0069ffdc
0069ffa8 78138cd9 msvcr80!_except_handler4
0069ffac d207e277
0069ffb0 00000000
0069ffb4 0069ffec
0069ffb8 781328c8 msvcr80!_endthread+0xcb
0069ffbc 7d4dfe21 kernel32!BaseThreadStart+0×34
0069ffc0 00595620
0069ffc4 00000000
0069ffc8 00000000
0069ffcc 00595620
0069ffd0 c0000005

Also we double check return addresses to see if they are valid code indeed. The best way is to try to disassemble them backwards. This should show call instructions resulted in saved return addresses:

0:001> ub WrongIP!internal_func_1+0x1f
WrongIP!internal_func_1+0x1:
00401871 mov     ebp,esp
00401873 push    offset WrongIP!GS_ExceptionPointers+0x38 (00402124)
00401878 call    dword ptr [WrongIP!_imp__puts (004020ac)]
0040187e add     esp,4
00401881 push    offset WrongIP!return_func (00401850)
00401886 mov     eax,dword ptr [ebp+8]
00401889 push    eax
0040188a call    WrongIP!internal_func_2 (004017e0)

0:001> ub WrongIP!thread_request+0xc
WrongIP!internal_func_1+0x2d:
0040189d int     3
0040189e int     3
0040189f int     3
WrongIP!thread_request:
004018a0 push    ebp
004018a1 mov     ebp,esp
004018a3 mov     eax,dword ptr [ebp+8]
004018a6 push    eax
004018a7 call    WrongIP!internal_func_1 (00401870)

0:001> ub msvcr80!_endthread+0x4b
msvcr80!_endthread+0x2f:
7813282c pop     esi
7813282d push    0Ch
7813282f push    offset msvcr80!__rtc_tzz+0x64 (781b4b98)
78132834 call    msvcr80!_SEH_prolog4 (78138c80)
78132839 call    msvcr80!_getptd (78132e29)
7813283e and     dword ptr [ebp-4],0
78132842 push    dword ptr [eax+58h]
78132845 call    dword ptr [eax+54h]

0:001> ub msvcr80!_endthread+0xcb
msvcr80!_endthread+0xaf:
781328ac mov     edx,dword ptr [ecx+58h]
781328af mov     dword ptr [eax+58h],edx
781328b2 mov     edx,dword ptr [ecx+4]
781328b5 push    ecx
781328b6 mov     dword ptr [eax+4],edx
781328b9 call    msvcr80!_freefls (78132e41)
781328be call    msvcr80!_initp_misc_winxfltr (781493c1)
781328c3 call    msvcr80!_endthread+0×30 (7813282d)

0:001> ub BaseThreadStart+0x34
kernel32!BaseThreadStart+0x10:
7d4dfdfd mov     eax,dword ptr fs:[00000018h]
7d4dfe03 cmp     dword ptr [eax+10h],1E00h
7d4dfe0a jne     kernel32!BaseThreadStart+0x2e (7d4dfe1b)
7d4dfe0c cmp     byte ptr [kernel32!BaseRunningInServerProcess (7d560008)],0
7d4dfe13 jne     kernel32!BaseThreadStart+0x2e (7d4dfe1b)
7d4dfe15 call    dword ptr [kernel32!_imp__CsrNewThread (7d4d0310)]
7d4dfe1b push    dword ptr [ebp+0Ch]
7d4dfe1e call    dword ptr [ebp+8]

Now we can use extended version of k command and supply custom EBP, ESP and EIP values. We set EBP to the first found address of EBP:PreviousEBP pair and set EIP to 0:

0:001> k L=0069ff60 0069ff60 0
ChildEBP RetAddr
WARNING: Frame IP not in any known module. Following frames may be wrong.
0069ff5c 0069ff70 0x0
0069ff60 0040188f 0x69ff70
0069ff70 004018ac WrongIP!internal_func_1+0x1f
0069ff7c 78132848 WrongIP!thread_request+0xc
0069ffb4 781328c8 msvcr80!_endthread+0x4b
0069ffb8 7d4dfe21 msvcr80!_endthread+0xcb
0069ffec 00000000 kernel32!BaseThreadStart+0x34

The stack trace looks good because it also shows BaseThreadStart.

From the backwards disassembly of the return address WrongIP!internal_func_1+0×1f we see that internal_func_1 calls internal_func_2 so we can disassemble the latter function:

0:001> uf internal_func_2
Flow analysis was incomplete, some code may be missing
WrongIP!internal_func_2:
   28 004017e0 push    ebp
   28 004017e1 mov     ebp,esp

   28 004017e3 sub     esp,8
   29 004017e6 mov     eax,dword ptr [ebp+8]
   29 004017e9 mov     dword ptr [ebp-4],eax

   30 004017ec mov     ecx,dword ptr [ebp+0Ch]
   30 004017ef mov     dword ptr [ebp-8],ecx
   32 004017f2 push    offset WrongIP!GS_ExceptionPointers+0×28 (00402114)
   32 004017f7 call    dword ptr [WrongIP!_imp__puts (004020ac)]
   32 004017fd add     esp,4
   33 00401800 push    8
   33 00401802 push    offset WrongIP!GS_ExceptionPointers+0×8 (004020f4)
   33 00401807 lea     edx,[ebp-8]
   33 0040180a push    edx
   33 0040180b call    WrongIP!memcpy (00401010)
   33 00401810 add     esp,0Ch
   35 00401813 push    dword ptr [ebp-8]
   36 00401816 mov     eax,dword ptr [ebp-4]
   37 00401819 mov     ebp,0
   38 0040181e jmp     eax

We see that it takes some value from [ebp-8], puts it into EAX and then jumps to that address. The function uses standard prolog (in blue) and therefore EBP-4 is the local variable. From the code we see that it comes from [EBP+8] which is the first function parameter:

EBP+C: second parameter
EBP+8: first parameter
EBP+4: return address
EBP:   previous EBP
EBP-4: local variable
EBP-8: local variable

If we examine the first parameter we would see it is a valid function address that we were supposed to call:

0:001> kv L=0069ff60 0069ff60 0
ChildEBP RetAddr  Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
0069ff5c 0069ff70 0040188f 00401830 00401850 0x0
0069ff60 0040188f 00401830 00401850 0069ff7c 0x69ff70
0069ff70 004018ac 00401830 0069ffb4 78132848 WrongIP!internal_func_1+0×1f
0069ff7c 78132848 00401830 6d5ba283 00000000 WrongIP!thread_request+0xc
0069ffb4 781328c8 7d4dfe21 00595620 00000000 msvcr80!_endthread+0×4b
0069ffb8 7d4dfe21 00595620 00000000 00000000 msvcr80!_endthread+0xcb
0069ffec 00000000 7813286e 00595620 00000000 kernel32!BaseThreadStart+0×34

0:001> u 00401830
WrongIP!jump_func:
00401830 push    ebp
00401831 mov     ebp,esp
00401833 push    offset WrongIP!GS_ExceptionPointers+0x1c (00402108)
00401838 call    dword ptr [WrongIP!_imp__puts (004020ac)]
0040183e add     esp,4
00401841 pop     ebp
00401842 ret
00401843 int     3

However if we look at the code we would see that we call memcpy with ebp-8 address and the number of bytes to copy is 8. In pseudo-code it would look like:

memcpy(ebp-8, 004020f4, 8);

   33 00401800 push    8
   33 00401802 push    offset WrongIP!GS_ExceptionPointers+0x8 (004020f4)
   33 00401807 lea     edx,[ebp-8]
   33 0040180a push    edx
   33 0040180b call    WrongIP!memcpy (00401010)
   33 00401810 add     esp,0Ch

If we examine 004020f4 address we would see that it contains 8 zeroes:

0:001> db 004020f4 l8
004020f4  00 00 00 00 00 00 00 00
       

Therefore memcpy overwrites our local variables that contain a jump address with zeroes. This explains why we have jumped to 0 address and why EIP was zero.

Finally our reconstructed stack trace looks like this:

WrongIP!internal_func_2+offset ; here we jump
WrongIP!internal_func_1+0x1f
WrongIP!thread_request+0xc
msvcr80!_endthread+0x4b
msvcr80!_endthread+0xcb
kernel32!BaseThreadStart+0x34

This was based on the fact that ESP was valid. If we have a zero or invalid ESP we can look at the entire raw stack range from thread environment block (TEB). Use !teb command to get thread stack range. In my example this command doesn’t work due to the lack of proper MS symbols but it reports TEB address and we can dump it:

0:001> !teb
TEB at 7efda000
error InitTypeRead( TEB )...

0:001> dd 7efda000 l3
7efda000 0069ffa4 006a0000 0069e000

Usually the second double word is the stack limit and the third is the stack base address so we can dump the range and start reconstructing stack trace for our example from the bottom of the stack (BaseThreadStart) or look after exception handling calls (shown in red):

0:001> dds 0069e000 006a0000
0069e000  00000000
0069e004  00000000
...
...
...
0069fb24  7d535b43 kernel32!UnhandledExceptionFilter+0×851



0069fbb0  0069fc20
0069fbb4  7d6354c9 ntdll!RtlDispatchException+0×11f
0069fbb8  0069fc38
0069fbbc  0069fc88
0069fc1c  00000000
0069fc20  00000000
0069fc24  7d61dd26 ntdll!NtRaiseException+0×12
0069fc28  7d61ea51 ntdll!KiUserExceptionDispatcher+0×29
0069fc2c  0069fc38



0069ff38  00000000
0069ff3c  00000000
0069ff40  00000000
0069ff44  00000000
0069ff48  00000000
0069ff4c  00000000
0069ff50  00000000
0069ff54  00000000
0069ff58  00000000
0069ff5c  00000000
0069ff60  0069ff70
0069ff64  0040188f WrongIP!internal_func_1+0×1f
0069ff68  00401830 WrongIP!jump_func
0069ff6c  00401850 WrongIP!return_func
0069ff70  0069ff7c
0069ff74  004018ac WrongIP!thread_request+0xc
0069ff78  00401830 WrongIP!jump_func
0069ff7c  0069ffb4
0069ff80  78132848 msvcr80!_endthread+0×4b
0069ff84  00401830 WrongIP!jump_func
0069ff88  6d5ba283
0069ff8c  00000000
0069ff90  00000000
0069ff94  00595620
0069ff98  c0000005
0069ff9c  0069ff88
0069ffa0  0069fb34
0069ffa4  0069ffdc
0069ffa8  78138cd9 msvcr80!_except_handler4
0069ffac  152916af
0069ffb0  00000000
0069ffb4  0069ffec
0069ffb8  781328c8 msvcr80!_endthread+0xcb
0069ffbc  7d4dfe21 kernel32!BaseThreadStart+0×34
0069ffc0  00595620
0069ffc4  00000000


- Dmitry Vostokov @ DumpAnalysis.org -

Selected Citrix Troubleshooting Tools

Monday, July 23rd, 2007

I’ve put an HTML version of the recently updated Selected Citrix Tools presentation:

Selected Citrix Tools (15.07.07)

It covers only public tools that I wrote and maintain. If you are interested in the broader spectrum of troubleshooting tools for Citrix environments please look at the following Citrix article:

http://support.citrix.com/article/CTX107572

- Dmitry Vostokov @ DumpAnalysis.org -

GDB for WinDbg Users (Part 6)

Sunday, July 22nd, 2007

Once we get backtrace in GDB or stack trace in WinDbg we are interested in concrete stack frames, their arguments and local variables. I slightly modified the program used in the previous part to include some local variables:

#include <stdio.h>

void func_1(int param_1, char param_2, int *param_3, char *param_4);
void func_2(int param_1, char param_2, int *param_3, char *param_4);
void func_3(int param_1, char param_2, int *param_3, char *param_4);
void func_4();

int   g_val_1;
char  g_val_2;
int  *g_pval_1 = &g_val_1;
char *g_pval_2 = &g_val_2;

int main()
{
  int   local_0 = 0;
  char *hello = "Hello World!";

  g_val_1 = 1;
  g_val_2 = '1';

  func_1(g_val_1, g_val_2, (int *)g_pval_1, (char *)g_pval_2);
  return 0;
}

void func_1(int param_1, char param_2, int *param_3, char *param_4)
{
   int local_1 = 1;

   g_val_1 = 2;
   g_val_2 = '2';

   param_3 = &local_1;

   func_2(g_val_1, g_val_2, param_3, param_4);
}

void func_2(int param_1, char param_2, int *param_3, char *param_4)
{
   int local_2 = 2;

   g_val_1 = 3;
   g_val_2 = '3';

  

   param_3 = &local_2;

   func_3(g_val_1, g_val_2, param_3, param_4);
}

void func_3(int param_1, char param_2, int *param_3, char *param_4)
{
   int local_3 = 3;

   *g_pval_1 += param_1;
   *g_pval_2 += param_2;

   func_4();
}

void func_4()
{
   puts("Hello World!");
}

In GDB the frame command is used to set the current stack frame. Then info args command can be used to list function arguments and info locals command can be used to list local variables:

(gdb) break func_4
Breakpoint 1 at 0x401455: file test.c, line 61.

(gdb) run
Starting program: C:\MinGW\examples/test.exe

Breakpoint 1, func_4 () at test.c:61
61         puts("Hello World!");

(gdb) bt
#0  func_4 () at test.c:61
#1  0x0040144d in func_3 (param_1=3, param_2=51 '3', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:56
#2  0x0040140c in func_2 (param_1=2, param_2=50 '2', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:46
#3  0x004013ba in func_1 (param_1=1, param_2=49 '1', param_3=0x22ff30,
    param_4=0x404070 "f") at test.c:34
#4  0x00401363 in main () at test.c:21

(gdb) frame
#0  func_4 () at test.c:61
61         puts("Hello World!");

(gdb) frame 0
#0  func_4 () at test.c:61
61         puts("Hello World!");

(gdb) info args
No arguments.

(gdb) info locals
No locals.

(gdb) frame 1
#1  0x0040144d in func_3 (param_1=3, param_2=51 '3', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:56
56         func_4();

(gdb) info args
param_1 = 3
param_2 = 51 '3'
param_3 = (int *) 0x22ff10
param_4 = 0x404070 "f"

(gdb) info locals
local_3 = 3
param_2 = 51 '3'

(gdb) frame 2
#2  0x0040140c in func_2 (param_1=2, param_2=50 '2', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:46
46         func_3(g_val_1, g_val_2, param_3, param_4);

(gdb) info args
param_1 = 2
param_2 = 50 '2'
param_3 = (int *) 0x22ff10
param_4 = 0x404070 "f"

(gdb) info locals
local_2 = 2
param_2 = 50 '2'

(gdb) frame 3
#3  0x004013ba in func_1 (param_1=1, param_2=49 '1', param_3=0x22ff30,
    param_4=0x404070 "f") at test.c:34
34         func_2(g_val_1, g_val_2, param_3, param_4);

(gdb) info args
param_1 = 1
param_2 = 49 '1'
param_3 = (int *) 0x22ff30
param_4 = 0x404070 "f"

(gdb) info locals
local_1 = 1
param_2 = 49 '1'

(gdb) frame 4
#4  0x00401363 in main () at test.c:21
21        func_1(g_val_1, g_val_2, (int *)g_pval_1, (char *)g_pval_2);

(gdb) info args
No arguments.

(gdb) info locals
local_0 = 0
hello = 0x403000 "Hello World!"

(gdb)

In WinDbg kn command shows stack trace with frame numbers, knL command additionally omits source code references, .frame command switches to particular stack frame, dv command shows parameters and local variables together, dv /i command classifies them into categories, parameters or locals, dv /V command shows their addresses and offsets for the relevant base frame register, usually EBP, dv /t command shows type information:

Microsoft (R) Windows Debugger  Version 6.7.0005.1
Copyright (c) Microsoft Corporation. All rights reserved.

CommandLine: C:\dmitri\test\release\test.exe
Symbol search path is: SRV*c:\websymbols*http://msdl.microsoft.com/download/symbols
Executable search path is:
ModLoad: 00400000 0040f000   test.exe
ModLoad: 7d4c0000 7d5f0000   NOT_AN_IMAGE
ModLoad: 7d600000 7d6f0000   C:\W2K3\SysWOW64\ntdll32.dll
ModLoad: 7d4c0000 7d5f0000   C:\W2K3\syswow64\kernel32.dll
(e38.ac0): Break instruction exception - code 80000003 (first chance)
eax=7d600000 ebx=7efde000 ecx=00000005 edx=00000020 esi=7d6a01f4 edi=00221f38
eip=7d61002d esp=0012fb4c ebp=0012fcac iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll32!DbgBreakPoint:
7d61002d cc              int     3

0:000> bp func_4

0:000> g
ModLoad: 71c20000 71c32000   C:\W2K3\SysWOW64\tsappcmp.dll
ModLoad: 77ba0000 77bfa000   C:\W2K3\syswow64\msvcrt.dll
ModLoad: 00410000 004ab000   C:\W2K3\syswow64\ADVAPI32.dll
ModLoad: 7da20000 7db00000   C:\W2K3\syswow64\RPCRT4.dll
ModLoad: 7d8d0000 7d920000   C:\W2K3\syswow64\Secur32.dll
Breakpoint 0 hit
eax=0040c9d4 ebx=7d4d8df9 ecx=0040c9d4 edx=00000066 esi=00000002 edi=00000ece
eip=00408be0 esp=0012ff10 ebp=0012ff18 iopl=0 nv up ei pl nz na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000206
test!func_4:
00408be0 55              push    ebp

0:000> knL
 # ChildEBP RetAddr
00 0012ff0c 00408c38 test!func_4
01 0012ff18 00408c7c test!func_3+0x38
02 0012ff34 00408ccc test!func_2+0x3c
03 0012ff50 00408d24 test!func_1+0x3c
04 0012ff70 00401368 test!main+0x44
05 0012ffc0 7d4e7d2a test!__tmainCRTStartup+0x15f
06 0012fff0 00000000 kernel32!BaseProcessStart+0x28

0:000> .frame
00 0012ff0c 00408c38 test!func_4 [c:\dmitri\test\test\test.cpp @ 60]

0:000> .frame 0
00 0012ff0c 00408c38 test!func_4 [c:\dmitri\test\test\test.cpp @ 60]

0:000> dv

0:000> .frame 1
01 0012ff18 00408c7c test!func_3+0x38 [c:\dmitri\test\test\test.cpp @ 57]

0:000> dv
        param_1 = 3
        param_2 = 51 '3'
        param_3 = 0x0012ff30
        param_4 = 0x0040c9d4 "f"
        local_3 = 3

0:000> dv /i
prv param  param_1 = 3
prv param  param_2 = 51 '3'
prv param  param_3 = 0x0012ff30
prv param  param_4 = 0x0040c9d4 "f"
prv local  local_3 = 3

0:000> dv /i /V
prv param  0012ff20 @ebp+0x08 param_1 = 3
prv param  0012ff24 @ebp+0x0c param_2 = 51 '3'
prv param  0012ff28 @ebp+0x10 param_3 = 0x0012ff30
prv param  0012ff2c @ebp+0x14 param_4 = 0x0040c9d4 "f"
prv local  0012ff14 @ebp-0x04 local_3 = 3

0:000> .frame 4
04 0012ff70 00401368 test!main+0x44 [c:\dmitri\test\test\test.cpp @ 21]

0:000> dv
        local_0 = 0
          hello = 0x0040a274 "Hello World!"

0:000> dv /i
prv local          local_0 = 0
prv local            hello = 0x0040a274 "Hello World!"

0:000> dv /i /V
prv local  0012ff68 @ebp-0x08         local_0 = 0
prv local  0012ff6c @ebp-0x04           hello = 0x0040a274 "Hello World!"

0:000> dv /t
int local_0 = 0
char * hello = 0x0040a274 "Hello World!"

Our comparison table grows a bit:

Action                      | GDB                 | WinDbg
----------------------------------------------------------------
Start the process           | run                 | g
Exit                        | (q)uit              | q
Disassemble (forward)       | (disas)semble       | uf, u
Disassemble N instructions  | x/<N>i              | -
Disassemble (backward)      | -                   | ub
Stack trace                 | backtrace (bt)      | k
Full stack trace            | bt full             | kv
Stack trace with parameters | bt full             | kP
Partial trace (innermost)   | bt <N>              | k <N>
Partial trace (outermost)   | bt -<N>             | -
Stack trace for all threads | thread apply all bt | ~*k
Breakpoint                  | break               | bp
Frame numbers               | any bt command      | kn
Select frame                | frame               | .frame
Display parameters          | info args           | dv /t /i /V
Display locals              | info locals         | dv /t /i /V

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 19)

Sunday, July 22nd, 2007

Almost all threads in any system are waiting for resources or waiting in a ready-to-run queues to be scheduled. At any moment of time the number of running threads is equal to the number of processors. The rest, hundreds and thousands of threads, are waiting. Looking at their waiting times in kernel and complete memory dumps provides some interesting observations that worth their own pattern name: Waiting Thread Time.

When a thread starts waiting that time is recorded in WaitTime field of _KTHREAD structure:

1: kd> dt _KTHREAD 8728a020
   +0x000 Header           : _DISPATCHER_HEADER
   +0x010 MutantListHead   : _LIST_ENTRY [ 0x8728a030 - 0x8728a030 ]
   +0x018 InitialStack     : 0xa3a1f000
   +0x01c StackLimit       : 0xa3a1a000
   +0x020 KernelStack      : 0xa3a1ec08
   +0x024 ThreadLock       : 0
   +0x028 ApcState         : _KAPC_STATE
   +0x028 ApcStateFill     : [23]  "H???"
   +0x03f ApcQueueable     : 0x1 ''
   +0x040 NextProcessor    : 0x3 ''
   +0x041 DeferredProcessor : 0x3 ''
   +0x042 AdjustReason     : 0 ''
   +0x043 AdjustIncrement  : 1 ''
   +0x044 ApcQueueLock     : 0
   +0x048 ContextSwitches  : 0x6b7
   +0x04c State            : 0x5 ''
   +0x04d NpxState         : 0xa ''
   +0x04e WaitIrql         : 0 ''
   +0x04f WaitMode         : 1 ''
   +0x050 WaitStatus       : 0
   +0x054 WaitBlockList    : 0x8728a0c8 _KWAIT_BLOCK
   +0x054 GateObject       : 0x8728a0c8 _KGATE
   +0x058 Alertable        : 0 ''
   +0x059 WaitNext         : 0 ''
   +0x05a WaitReason       : 0x11 ''
   +0x05b Priority         : 12 ''
   +0x05c EnableStackSwap  : 0x1 ''
   +0x05d SwapBusy         : 0 ''
   +0x05e Alerted          : [2]  ""
   +0x060 WaitListEntry    : _LIST_ENTRY [ 0x88091e10 - 0x88029ce0 ]
   +0x060 SwapListEntry    : _SINGLE_LIST_ENTRY
   +0x068 Queue            : (null)
   +0×06c WaitTime         : 0×82de9b
   +0×070 KernelApcDisable : 0


This value is also displayed in decimal format as Wait Start TickCount when you list threads or use !thread command:

0: kd> ? 0x82de9b
Evaluate expression: 8576667 = 0082de9b

1: kd> !thread 8728a020
THREAD 8728a020  Cid 4c9c.59a4  Teb: 7ffdf000 Win32Thread: bc012008 WAIT: (Unknown) UserMode Non-Alertable
    8728a20c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 017db413:
Current LPC port e5fcff68
Impersonation token:  e2b07028 (Level Impersonation)
DeviceMap                 e1da6518
Owning Process            89d20740       Image:         winlogon.exe
Wait Start TickCount      8576667        Ticks: 7256 (0:00:01:53.375)
Context Switch Count      1719                 LargeStack
UserTime                  00:00:00.0359
KernelTime                00:00:00.0375

Tick is a system unit of time and KeTimeIncrement double word value contains its equivalent as the number of 100-nanosecond units:

0: kd> dd KeTimeIncrement l1
808a6304  0002625a

0: kd> ? 0002625a
Evaluate expression: 156250 = 0002625a

0: kd> ?? 156250.0/10000000.0
double 0.015625

Therefore on that system one tick is 0.015625 of a second.

The current tick count is available via KeTickCount variable:

0: kd> dd KeTickCount l1
8089c180  0082faf3

If we subtract the recorded start wait time from the current tick count we get the number of ticks passed since the thread began waiting:

0: kd> ? 0082faf3-82de9b
Evaluate expression: 7256 = 00001c58

Using our previously calculated constant of the number of seconds per tick (0.015625) we get the number of seconds passed:

0: kd> ?? 7256.0 * 0.015625
double 113.37499999999999

113.375 seconds is 1 minute 53 seconds and 375 milliseconds:

0: kd> ?? 113.375-60.0
double 53.374999999999986

We can see that this value corresponds to Ticks value that WinDbg shows for the thread:

Wait Start TickCount 8576667 Ticks: 7256 (0:00:01:53.375)

Why do we need to concern ourselves with these ticks? If we know that some activity was frozen for 15 minutes we can filter out threads from our search space because threads with significantly less number of ticks were running at some time and were not waiting for 15 minutes.

Threads with low number of ticks were running recently:

THREAD 86ced020  Cid 0004.3908  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    b99cb7d0  QueueObject
    86ced098  NotificationTimer
Not impersonating
DeviceMap                 e10038e0
Owning Process            8ad842a8       Image:         System
Wait Start TickCount      8583871        Ticks: 52 (0:00:00:00.812)
Context Switch Count      208
UserTime                  00:00:00.0000
KernelTime                00:00:00.0000
Start Address rdbss!RxWorkerThreadDispatcher (0xb99cdc2e)
Stack Init ad21d000 Current ad21ccd8 Base ad21d000 Limit ad21a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement
ChildEBP RetAddr
ad21ccf0 808330c6 nt!KiSwapContext+0×26
ad21cd1c 8082af7f nt!KiSwapThread+0×284
ad21cd64 b99c00e9 nt!KeRemoveQueue+0×417
ad21cd9c b99cdc48 rdbss!RxpWorkerThreadDispatcher+0×4b
ad21cdac 80948e74 rdbss!RxWorkerThreadDispatcher+0×1a
ad21cddc 8088d632 nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

Another application would be to find all threads from different processes whose wait time roughly corresponds to 15 minutes and therefore they might be related to the same frozen activity. For example, these RPC threads below from different processes are most likely related because one is the RPC client thread, the other is the RPC server thread waiting for some object and their common Ticks value is the same: 15131.

THREAD 89cc9750  Cid 0f1c.0f60  Teb: 7ffd6000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    89cc993c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0000a7e7:
Current LPC port e18fcae8
Not impersonating
DeviceMap                 e10018a8
Owning Process            88d3b938       Image:         svchost.exe
Wait Start TickCount      29614          Ticks: 15131 (0:00:03:56.421)
Context Switch Count      45
UserTime                  00:00:00.0000
KernelTime                00:00:00.0000
Win32 Start Address 0×0000a7e6
LPC Server thread working on message Id a7e6
Start Address kernel32!BaseThreadStartThunk (0×7c82b5bb)
Stack Init f29a6000 Current f29a5c08 Base f29a6000 Limit f29a3000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
f29a5c20 80832f7a nt!KiSwapContext+0×26
f29a5c4c 8082927a nt!KiSwapThread+0×284
f29a5c94 8091df86 nt!KeWaitForSingleObject+0×346
f29a5d50 80888c6c nt!NtRequestWaitReplyPort+0×776
f29a5d50 7c94ed54 nt!KiFastCallEntry+0xfc
0090f6b8 7c941c94 ntdll!KiFastSystemCallRet
0090f6bc 77c42700 ntdll!NtRequestWaitReplyPort+0xc
0090f708 77c413ba RPCRT4!LRPC_CCALL::SendReceive+0×230
0090f714 77c42c7f RPCRT4!I_RpcSendReceive+0×24
0090f728 77cb5d63 RPCRT4!NdrSendReceive+0×2b
0090f9cc 67b610ca RPCRT4!NdrClientCall+0×334
0090f9dc 67b61c07 component!NotifyOfEvent+0×14



0090ffec 00000000 kernel32!BaseThreadStart+0×34

THREAD 89b49590  Cid 098c.01dc  Teb: 7ff92000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    88c4e020  Thread
    89b49608  NotificationTimer
Not impersonating
DeviceMap                 e10018a8
Owning Process            89d399c0       Image:         MyService.exe
Wait Start TickCount      29614          Ticks: 15131 (0:00:03:56.421)
Context Switch Count      310
UserTime                  00:00:00.0015
KernelTime                00:00:00.0000
Win32 Start Address 0×0000a7e7
LPC Server thread working on message Id a7e7
Start Address kernel32!BaseThreadStartThunk (0×7c82b5bb)
Stack Init f2862000 Current f2861c60 Base f2862000 Limit f285f000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
f2861c78 80832f7a nt!KiSwapContext+0×26
f2861ca4 8082927a nt!KiSwapThread+0×284
f2861cec 80937e4c nt!KeWaitForSingleObject+0×346
f2861d50 80888c6c nt!NtWaitForSingleObject+0×9a
f2861d50 7c94ed54 nt!KiFastCallEntry+0xfc
0a6cf590 7c942124 ntdll!KiFastSystemCallRet
0a6cf594 7c82baa8 ntdll!NtWaitForSingleObject+0xc
0a6cf604 7c82ba12 kernel32!WaitForSingleObjectEx+0xac
0a6cf618 3f691c11 kernel32!WaitForSingleObject+0×12
0a6cf658 09734436 component2!WaitForResponse+0×75



0a6cf8b4 77cb23f7 RPCRT4!Invoke+0×30
0a6cfcb4 77cb26ed RPCRT4!NdrStubCall2+0×299
0a6cfcd0 77c409be RPCRT4!NdrServerCall2+0×19
0a6cfd04 77c4093f RPCRT4!DispatchToStubInCNoAvrf+0×38
0a6cfd58 77c40865 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×117
0a6cfd7c 77c357eb RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3
0a6cfdbc 77c41e26 RPCRT4!RPC_INTERFACE::DispatchToStubWithObject+0xc0
0a6cfdfc 77c41bb3 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×42c
0a6cfe20 77c45458 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127
0a6cff84 77c2778f RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430
0a6cff8c 77c2f7dd RPCRT4!RecvLotsaCallsWrapper+0xd
0a6cffac 77c2de88 RPCRT4!BaseCachedThreadRoutine+0×9d
0a6cffb8 7c826063 RPCRT4!ThreadStartRoutine+0×1b
0a6cffec 00000000 kernel32!BaseThreadStart+0×34

- Dmitry Vostokov @ DumpAnalysis.org -

Reading Windows-based Code (Part 2)

Saturday, July 21st, 2007

The HTML version of the presentation is located here:

Reading Windows-based Code (Part 2)

This second part is still based on the first chapters from “Code Reading: The Open Source Perspective” book written by Diomidis Spinellis. As I mentioned in the first presentation (slide 2) that book never uses Windows-based code and this prompted me to start Code Reading (The Windows Perspective) series.

The 3rd part coming next week will be mostly about basic data types and introduce some Windows conventions related to them. 

- Dmitry Vostokov @ DumpAnalysis.org -

Interrupts and exceptions explained (Part 5)

Friday, July 20th, 2007

In this part I’ll show how to simulate .trap WinDbg command when you have x64 Windows kernel and complete memory dumps. 

When you have a fault an x64 processor saves some registers on the current thread stack as explained previously in Part 2. Then an interrupt handler saves _KTRAP_FRAME on the stack:

6: kd> uf nt!KiPageFault
nt!KiPageFault:
fffff800`0102d400 push    rbp
fffff800`0102d401 sub     rsp,158h
fffff800`0102d408 lea     rbp,[rsp+80h]
fffff800`0102d410 mov     byte ptr [rbp-55h],1
fffff800`0102d414 mov     qword ptr [rbp-50h],rax
fffff800`0102d418 mov     qword ptr [rbp-48h],rcx
fffff800`0102d41c mov     qword ptr [rbp-40h],rdx
fffff800`0102d420 mov     qword ptr [rbp-38h],r8
fffff800`0102d424 mov     qword ptr [rbp-30h],r9
fffff800`0102d428 mov     qword ptr [rbp-28h],r10
fffff800`0102d42c mov     qword ptr [rbp-20h],r11
...
...
...

6: kd> dt _KTRAP_FRAME
   +0x000 P1Home           : Uint8B
   +0x008 P2Home           : Uint8B
   +0x010 P3Home           : Uint8B
   +0x018 P4Home           : Uint8B
   +0x020 P5               : Uint8B
   +0x028 PreviousMode     : Char
   +0x029 PreviousIrql     : UChar
   +0x02a FaultIndicator   : UChar
   +0x02b ExceptionActive  : UChar
   +0x02c MxCsr            : Uint4B
   +0x030 Rax              : Uint8B
   +0x038 Rcx              : Uint8B
   +0x040 Rdx              : Uint8B
   +0x048 R8               : Uint8B
   +0x050 R9               : Uint8B
   +0x058 R10              : Uint8B
   +0x060 R11              : Uint8B
   +0x068 GsBase           : Uint8B
   +0x068 GsSwap           : Uint8B
   +0x070 Xmm0             : _M128A
   +0x080 Xmm1             : _M128A
   +0x090 Xmm2             : _M128A
   +0x0a0 Xmm3             : _M128A
   +0x0b0 Xmm4             : _M128A
   +0x0c0 Xmm5             : _M128A
   +0x0d0 FaultAddress     : Uint8B
   +0x0d0 ContextRecord    : Uint8B
   +0x0d0 TimeStamp        : Uint8B
   +0x0d8 Dr0              : Uint8B
   +0x0e0 Dr1              : Uint8B
   +0x0e8 Dr2              : Uint8B
   +0x0f0 Dr3              : Uint8B
   +0x0f8 Dr6              : Uint8B
   +0x100 Dr7              : Uint8B
   +0x108 DebugControl     : Uint8B
   +0x110 LastBranchToRip  : Uint8B
   +0x118 LastBranchFromRip : Uint8B
   +0x120 LastExceptionToRip : Uint8B
   +0x128 LastExceptionFromRip : Uint8B
   +0x108 LastBranchControl : Uint8B
   +0x110 LastBranchMSR    : Uint4B
   +0x130 SegDs            : Uint2B
   +0x132 SegEs            : Uint2B
   +0x134 SegFs            : Uint2B
   +0x136 SegGs            : Uint2B
   +0x138 TrapFrame        : Uint8B
   +0x140 Rbx              : Uint8B
   +0x148 Rdi              : Uint8B
   +0x150 Rsi              : Uint8B
   +0x158 Rbp              : Uint8B
   +0×160 ErrorCode        : Uint8B
   +0×160 ExceptionFrame   : Uint8B
   +0×168 Rip              : Uint8B
   +0×170 SegCs            : Uint2B
   +0×172 Fill1            : [3] Uint2B
   +0×178 EFlags           : Uint4B
   +0×17c Fill2            : Uint4B
   +0×180 Rsp              : Uint8B
   +0×188 SegSs            : Uint2B
   +0×18a Fill3            : [1] Uint2B
   +0×18c CodePatchCycle   : Int4B

Unfortunately the technique to use DS and ES pair to find the trap frame in x86 Windows crash dump doesn’t work here because KiPageFault interrupt handler doesn’t save them as can be found by inspecting its disassembly. Fortunately the registers that an x64 processor pushes upon an interrupt are part of _KTRAP_FRAME shown in blue above. Fill1, Fill2, Fill3 and CodePatchCycle are just dummy values to fill 64-bit slots because CS and SS are 16-bit registers and in 64-bit RFLAGS only the first 32-bit EFLAGS part is currently used. Remember that a processor in 64-bit mode pushes 64-bit values even if values occupy only 16 or 32-bit. Therefore we can try to find CS and SS on the stack because they have the following constant values:

6: kd> r cs
cs=0010
6: kd> r ss
ss=0018

6: kd> k
Child-SP          RetAddr           Call Site
fffffadc`6e02b9e8 fffff800`013731b1 nt!KeBugCheckEx



fffffadc`6e02cd70 fffff800`010202d6 nt!PspSystemThreadStartup+0×3e
fffffadc`6e02cdd0 00000000`00000000 nt!KxStartSystemThread+0×16

6: kd> dqs fffffadc`6e02b9e8 fffffadc`6e02cd70
...
...
...
fffffadc`6e02c938 fffff800`0102d5e1 nt!KiPageFault+0x1e1
...
...
...
fffffadc`6e02ca70  fffff97f`f3937a8c
fffffadc`6e02ca78  fffff97f`ff57d28b driver+0x3028b
fffffadc`6e02ca80  00000000`00000000
fffffadc`6e02ca88  fffff97f`f3937030
fffffadc`6e02ca90  fffff97f`ff5c2990 driver+0x75990
fffffadc`6e02ca98  00000000`00000000
fffffadc`6e02caa0  00000000`00000000 ; ErrorCode
fffffadc`6e02caa8  fffff97f`ff591ed3 driver+0x44ed3 ; RIP
fffffadc`6e02cab0  00000000`00000010 ; CS
fffffadc`6e02cab8  00000000`00010282 ; RFLAGS
fffffadc`6e02cac0  fffffadc`6e02cad0 ; RSP
fffffadc`6e02cac8  00000000`00000018 ; SS
fffffadc`6e02cad0  fffff97f`f382b0e0
fffffadc`6e02cad8  fffffadc`6e02cbd0
fffffadc`6e02cae0  fffff97f`f3937a8c
fffffadc`6e02cae8  fffff97f`f3937030
fffffadc`6e02caf0  00000000`00000000
fffffadc`6e02caf8  00000000`00000001


Now we can calculate the trap frame address by subtracting SegSs offset in _KTRAP_FRAME structure (0×188) from fffffadc`6e02cac8 address:

6: kd> ? fffffadc`6e02cac8-188
Evaluate expression: -5650331285184 = fffffadc`6e02c940

6: kd> .trap fffffadc`6e02c940
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed.
rax=fffffadcdac27298 rbx=0000000000000000 rcx=fffffadcdb45a4c0
rdx=0000000000000555 rsi=fffff97fff5c2990 rdi=fffff97ff3937030
rip=fffff97fff591ed3 rsp=fffffadc6e02cad0 rbp=0000000000000000
 r8=fffffadcdac27250  r9=fffff97ff3824030 r10=0000000000000020
r11=fffffadcdac27250 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei ng nz na pe nc
driver+0x44ed3:
fffff97f`ff591ed3 0fb74514  movzx eax,word ptr [rbp+14h] ss:0018:00000000`00000014=????

6: kd> k
Child-SP          RetAddr           Call Site
fffffadc`6e02cad0 fffff97f`ff5935f7 driver+0x44ed3
fffffadc`6e02cc40 fffff800`0124b972 driver+0x465f7
fffffadc`6e02cd70 fffff800`010202d6 nt!PspSystemThreadStartup+0x3e
fffffadc`6e02cdd0 00000000`00000000 nt!KxStartSystemThread+0x16

Our example shows how to find a trap frame manually in x64 kernel or complete memory dump. Usually WinDbg finds trap frames automatically (call arguments are removed from the verbose stack trace for clarity):

6: kd> kv
Child-SP          RetAddr           Call Site
fffffadc`6e02b9e8 fffff800`013731b1 nt!KeBugCheckEx
fffffadc`6e02b9f0 fffff800`010556ab nt!PspSystemThreadStartup+0x270
fffffadc`6e02ba40 fffff800`010549fd nt!_C_specific_handler+0x9b
fffffadc`6e02bad0 fffff800`01054f93 nt!RtlpExecuteHandlerForException+0xd
fffffadc`6e02bb00 fffff800`0100b901 nt!RtlDispatchException+0x2c0
fffffadc`6e02c1c0 fffff800`0102e76f nt!KiDispatchException+0xd9
fffffadc`6e02c7c0 fffff800`0102d5e1 nt!KiExceptionExit
fffffadc`6e02c940 fffff97f`ff591ed3 nt!KiPageFault+0x1e1 (TrapFrame @ fffffadc`6e02c940)
fffffadc`6e02cad0 fffff97f`ff5935f7 driver+0×44ed3
fffffadc`6e02cc40 fffff800`0124b972 driver+0×465f7
fffffadc`6e02cd70 fffff800`010202d6 nt!PspSystemThreadStartup+0×3e
fffffadc`6e02cdd0 00000000`00000000 nt!KxStartSystemThread+0×16

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 18)

Friday, July 20th, 2007

Sometimes the page file size is less than the amount of physical memory. If this is the case and we have configured “Complete memory dump” in Startup and Recovery settings in Control Panel we get truncated dumps. Therefore we can call our next pattern “Truncated Dump”. WinDbg prints a warning when we open such dump:

************************************************************
WARNING: Dump file has been truncated.  Data may be missing.
************************************************************

We can double check this with !vm command:

kd> !vm

*** Virtual Memory Usage ***
       Physical Memory:      511859 (   2047436 Kb)
       Paging File Name paged out
         Current:   1536000 Kb  Free Space:   1522732 Kb
         Minimum:   1536000 Kb  Maximum:      1536000 Kb

We see that the page file size is 1.5Gb but the amount of physical memory is 2Gb. When BSOD happens the physical memory contents will be saved to the page file and the dump file size will be no more than 1.5Gb effectively truncating data needed for crash dump analysis.

Sometimes you can still access some data in truncated dumps but pay attention to what WinDbg says. For example, in the truncated dump shown above the stack and driver code are not available:

kd> kv
ChildEBP RetAddr  Args to Child
WARNING: Stack unwind information not available. Following frames may be wrong.
f408b004 00000000 00000000 00000000 00000000 driver+0x19237

kd> r
Last set context:
eax=89d55230 ebx=89d21130 ecx=89d21130 edx=89c8cc20 esi=89e24ac0 edi=89c8cc20
eip=f7242237 esp=f408afec ebp=f408b004 iopl=0 nv up ei ng nz ac po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010292
driver+0x19237:
f7242237 ??              ???

kd> dds esp
f408afec  ????????
f408aff0  ????????
f408aff4  ????????
f408aff8  ????????
f408affc  ????????
f408b000  ????????
f408b004  ????????
f408b008  ????????
f408b00c  ????????
f408b010  ????????
f408b014  ????????
f408b018  ????????
f408b01c  ????????
f408b020  ????????
f408b024  ????????
f408b028  ????????
f408b02c  ????????
f408b030  ????????
f408b034  ????????
f408b038  ????????
f408b03c  ????????
f408b040  ????????
f408b044  ????????
f408b048  ????????
f408b04c  ????????
f408b050  ????????
f408b054  ????????
f408b058  ????????
f408b05c  ????????
f408b060  ????????
f408b064  ????????
f408b068  ????????

kd> lmv m driver
start    end        module name
f7229000 f725f000   driver     T (no symbols)
    Loaded symbol image file: driver.sys
    Image path: driver.sys
    Image name: driver.sys
    Timestamp:        unavailable (FFFFFFFE)
    CheckSum:         missing
    ImageSize:        00036000

kd> dd f7229000
f7229000  ???????? ???????? ???????? ????????
f7229010  ???????? ???????? ???????? ????????
f7229020  ???????? ???????? ???????? ????????
f7229030  ???????? ???????? ???????? ????????
f7229040  ???????? ???????? ???????? ????????
f7229050  ???????? ???????? ???????? ????????
f7229060  ???????? ???????? ???????? ????????
f7229070  ???????? ???????? ???????? ????????

If due to some reasons you cannot increase the size of your page file then just configure “Kernel memory dump” in Startup and Recovery. For most all bugchecks kernel memory dump is sufficient except manual crash dumps when you need to inspect user process space.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 17)

Friday, July 20th, 2007

.NET programs also crash either from defects in .NET runtime (Common Language Runtime, CLR) or from non-handled runtime exceptions in managed code executed by .NET virtual machine. The latter exceptions are re-thrown from .NET runtime to be handled by operating system and intercepted by native debuggers. Therefore our next crash dump analysis pattern is called Managed Code Exception

When you get a dump from .NET application it is the dump from a native process. !analyze -v output can usually tell you that exception is actually CLR exception and give you other hints to look at managed code stack (CLR stack):

FAULTING_IP:
kernel32!RaiseException+53
77e4bee7 5e              pop     esi

EXCEPTION_RECORD:  ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 77e4bee7 (kernel32!RaiseException+0x00000053)
   ExceptionCode: e0434f4d (CLR exception)
   ExceptionFlags: 00000001
NumberParameters: 1
   Parameter[0]: 80131604

DEFAULT_BUCKET_ID:  CLR_EXCEPTION

PROCESS_NAME:  mmc.exe

ERROR_CODE: (NTSTATUS) 0xe0434f4d - <Unable to get error code text>

MANAGED_STACK: !dumpstack -EE
No export dumpstack found

STACK_TEXT:
05faf3d8 79f97065 e0434f4d 00000001 00000001 kernel32!RaiseException+0x53
WARNING: Stack unwind information not available. Following frames may be wrong.
05faf438 7a0945a4 023f31e0 00000000 00000000 mscorwks!DllCanUnloadNowInternal+0×37a9
05faf4fc 00f2f00a 02066be4 02085ee8 023d0df0 mscorwks!CorLaunchApplication+0×12005
05faf500 02066be4 02085ee8 023d0df0 023d0e2c 0xf2f00a
05faf504 02085ee8 023d0df0 023d0e2c 05e00dfa 0×2066be4
05faf508 023d0df0 023d0e2c 05e00dfa 023d0e10 0×2085ee8
05faf50c 023d0e2c 05e00dfa 023d0e10 05351d30 0×23d0df0
05faf510 05e00dfa 023d0e10 05351d30 023d0e10 0×23d0e2c

FOLLOWUP_IP:
mscorwks!DllCanUnloadNowInternal+37a9
79f97065 c745fcfeffffff  mov     dword ptr [ebp-4],0FFFFFFFEh

SYMBOL_NAME:  mscorwks!DllCanUnloadNowInternal+37a9

MODULE_NAME: mscorwks

IMAGE_NAME:  mscorwks.dll

PRIMARY_PROBLEM_CLASS:  CLR_EXCEPTION

BUGCHECK_STR:  APPLICATION_FAULT_CLR_EXCEPTION

Sometimes you can see mscorwks.dll on raw stack or see it loaded and find it on other thread stacks than the current one.

When you get such hints you might want to get managed code stack as well. First you need to load the appropriate WinDbg SOS extension (Son of Strike) corresponding to .NET runtime version. This can be done by the following command:

0:015> .loadby sos mscorwks

You can check which SOS extension version was loaded this by using .chain command:

0:015> .chain
Extension DLL search Path:
...
...
...
Extension DLL chain:
    C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\sos: image 2.0.50727.42, API 1.0.0, built Fri Sep 23 08:27:26 2005
        [path: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\sos.dll]

    dbghelp: image 6.6.0007.5, API 6.0.6, built Sat Jul 08 21:11:32 2006
        [path: C:\Program Files\Debugging Tools for Windows\dbghelp.dll]
    ext: image 6.6.0007.5, API 1.0.0, built Sat Jul 08 21:10:52 2006
        [path: C:\Program Files\Debugging Tools for Windows\winext\ext.dll]
    exts: image 6.6.0007.5, API 1.0.0, built Sat Jul 08 21:10:48 2006
        [path: C:\Program Files\Debugging Tools for Windows\WINXP\exts.dll]
    uext: image 6.6.0007.5, API 1.0.0, built Sat Jul 08 21:11:02 2006
        [path: C:\Program Files\Debugging Tools for Windows\winext\uext.dll]
    ntsdexts: image 6.0.5457.0, API 1.0.0, built Sat Jul 08 21:29:38 2006
        [path: C:\Program Files\Debugging Tools for Windows\WINXP\ntsdexts.dll]

Then you can use !dumpstack to dump the current stack or !EEStack command to dump all thread stacks. The native stack trace would be mixed with managed stack trace:

0:015> !dumpstack
OS Thread Id: 0x16e8 (15)
Current frame: kernel32!RaiseException+0x53
ChildEBP RetAddr Caller,Callee
05faf390 77e4bee7 kernel32!RaiseException+0x53, calling ntdll!RtlRaiseException
05faf3a8 79e814da mscorwks!Binder::RawGetClass+0x23, calling mscorwks!Module::LookupTypeDef
05faf3bc 79e87ff4 mscorwks!Binder::IsClass+0x21, calling mscorwks!Binder::RawGetClass
05faf3c8 79f958b8 mscorwks!Binder::IsException+0x13, calling mscorwks!Binder::IsClass
05faf3d8 79f97065 mscorwks!RaiseTheExceptionInternalOnly+0x226, calling kernel32!RaiseException
05faf438 7a0945a4 mscorwks!JIT_Throw+0xd0, calling mscorwks!RaiseTheExceptionInternalOnly
05faf4ac 7a0944ea mscorwks!JIT_Throw+0x1e, calling mscorwks!LazyMachStateCaptureState
05faf4c8 793d424e (MethodDesc 0x7924ad68 +0x2e System.Threading.WaitHandle.WaitOne(Int64, Boolean)), calling mscorwks!WaitHandleNative::CorWaitOneNative
05faf4fc 00f2f00a (MethodDesc 0x4f97500 +0x9a Ironring.Management.MMC.SnapinBase+MmcWindow.Invoke(System.Delegate, System.Object[])), calling mscorwks!JIT_Throw
05faf510 05e00dfa (MethodDesc 0×4f98fd8 +0xca MyNamespace.MyClass.MyMethod(Boolean)), calling 05fc7124
05faf55c 00f62fbc (MethodDesc 0×4f95f90 +0×16f4 MyNamespace.MyClass.MyMethod.Initialise(System.Object))

05faf740 793d912f (MethodDesc 0×7925fc70 +0×2f System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object))
05faf748 793683dd (MethodDesc 0×7913f3d0 +0×81 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
05faf75c 793d9218 (MethodDesc 0×7925fc80 +0×6c System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)), calling (MethodDesc 0×7913f3d0 +0 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
05faf774 79e88f63 mscorwks!CallDescrWorker+0×33
05faf784 79e88ee4 mscorwks!CallDescrWorkerWithHandler+0xa3, calling mscorwks!CallDescrWorker
05faf804 79f20212 mscorwks!DispatchCallBody+0×1e, calling mscorwks!CallDescrWorkerWithHandler
05faf824 79f201bc mscorwks!DispatchCallDebuggerWrapper+0×3d, calling mscorwks!DispatchCallBody
05faf888 79f2024b mscorwks!DispatchCallNoEH+0×51, calling mscorwks!DispatchCallDebuggerWrapper
05faf8bc 7a07bdf0 mscorwks!Holder,2>::~Holder,2>+0xbb, calling mscorwks!DispatchCallNoEH
05faf90c 77e61d1e kernel32!WaitForSingleObjectEx+0xac, calling ntdll!ZwWaitForSingleObject
05faf91c 79ecb4a4 mscorwks!Thread::UserResumeThread+0xfb
05faf92c 79ecb442 mscorwks!Thread::DoADCallBack+0×355, calling mscorwks!Thread::UserResumeThread+0xae
05faf950 79e74afe mscorwks!Thread::EnterRuntimeNoThrow+0×9b, calling mscorwks!_EH_epilog3
05faf988 79e77fe8 mscorwks!PEImage::LoadImage+0×1e1, calling mscorwks!_SEH_epilog4
05faf9c0 79ecb364 mscorwks!Thread::DoADCallBack+0×541, calling mscorwks!Thread::DoADCallBack+0×2a5
05faf9fc 7a0e1b7e mscorwks!Thread::DoADCallBack+0×575, calling mscorwks!Thread::DoADCallBack+0×4d4
05fafa24 7a0e1bab mscorwks!ManagedThreadBase::ThreadPool+0×13, calling mscorwks!Thread::DoADCallBack+0×550
05fafa38 7a07cae8 mscorwks!QueueUserWorkItemCallback+0×9d, calling mscorwks!ManagedThreadBase::ThreadPool
05fafa54 7a07ca48 mscorwks!QueueUserWorkItemCallback, calling mscorwks!UnwindAndContinueRethrowHelperAfterCatch
05fafa90 7a110f08 mscorwks!ThreadpoolMgr::ExecuteWorkRequest+0×40
05fafaa8 7a112328 mscorwks!ThreadpoolMgr::WorkerThreadStart+0×1f2, calling mscorwks!ThreadpoolMgr::ExecuteWorkRequest
05fafad0 79e7839d mscorwks!EEHeapFreeInProcessHeap+0×21, calling mscorwks!EEHeapFree
05fafae0 79e782dc mscorwks!operator delete[]+0×30, calling mscorwks!EEHeapFreeInProcessHeap
05fafb14 79ecb00b mscorwks!Thread::intermediateThreadProc+0×49
05fafb48 77e65512 kernel32!FlsSetValue+0xc7, calling kernel32!_SEH_epilog
05fafb6c 75da14d0 sxs!_calloc_crt+0×19, calling sxs!calloc
05fafb80 77e65512 kernel32!FlsSetValue+0xc7, calling kernel32!_SEH_epilog
05fafb88 75da1401 sxs!_CRT_INIT+0×17e, calling sxs!_initptd
05fafb8c 75da1408 sxs!_CRT_INIT+0×185, calling kernel32!GetCurrentThreadId
05fafb9c 30403805 MMCFormsShim!DllMain+0×15, calling MMCFormsShim!PrxDllMain
05fafbb0 30418b69 MMCFormsShim!__DllMainCRTStartup+0×7a, calling MMCFormsShim!DllMain
05fafbdc 75de0e4c sxs!_SxsDllMain+0×87, calling sxs!DllStartup_CrtInit
05fafbf0 30418bf9 MMCFormsShim!__DllMainCRTStartup+0×10a, calling MMCFormsShim!__SEH_epilog4
05fafbf4 30418c22 MMCFormsShim!_DllMainCRTStartup+0×1d, calling MMCFormsShim!__DllMainCRTStartup
05fafbfc 7c81a352 ntdll!LdrpCallInitRoutine+0×14
05fafc24 7c82ee8b ntdll!LdrpInitializeThread+0×1a5, calling ntdll!RtlLeaveCriticalSection
05fafc2c 7c82edec ntdll!LdrpInitializeThread+0×18f, calling ntdll!_SEH_epilog
05fafc7c 7c82ed71 ntdll!LdrpInitializeThread+0xd8, calling ntdll!RtlActivateActivationContextUnsafeFast
05fafc80 7c82ed35 ntdll!LdrpInitializeThread+0×12c, calling ntdll!RtlDeactivateActivationContextUnsafeFast
05fafcb4 7c82edec ntdll!LdrpInitializeThread+0×18f, calling ntdll!_SEH_epilog
05fafcb8 7c827c3b ntdll!NtTestAlert+0xc
05fafcbc 7c82ecb1 ntdll!_LdrpInitialize+0×1de, calling ntdll!_SEH_epilog
05fafd10 7c82ecb1 ntdll!_LdrpInitialize+0×1de, calling ntdll!_SEH_epilog
05fafd14 7c826d9b ntdll!NtContinue+0xc
05fafd18 7c8284da ntdll!KiUserApcDispatcher+0×3a, calling ntdll!NtContinue
05faffa4 79ecaff9 mscorwks!Thread::intermediateThreadProc+0×37, calling mscorwks!_alloca_probe_16
05faffb8 77e64829 kernel32!BaseThreadStart+0×34

.NET language symbolic names are usually reconstructed from .NET assembly metadata. 

You can examine a CLR exception and get managed stack trace by using !PrintException and !CLRStack commands, for example:

0:014> !PrintException
Exception object: 02320314
Exception type: System.Reflection.TargetInvocationException
Message: Exception has been thrown by the target of an invocation.
InnerException: System.Runtime.InteropServices.COMException, use !PrintException 023201a8 to see more
StackTrace (generated):
    SP       IP       Function
    075AF4FC 016BFD9A Ironring.Management.MMC.SnapinBase+MmcWindow.Invoke(System.Delegate, System.Object[])
    ...
    ...
    ...
    075AF740 793D87AF System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)
    075AF748 793608FD System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
    075AF760 793D8898 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)

StackTraceString: <none>
HResult: 80131604

0:014> !PrintException 023201a8
Exception object: 023201a8
Exception type: System.Runtime.InteropServices.COMException
Message: Error HRESULT E_FAIL has been returned from a call to a COM component.
InnerException: <none>
StackTrace (generated):
    SP       IP       Function
    00000000 00000001 Ironring.Management.MMC.IMMCFormsShim.HostUserControl3(System.Object, System.Object, System.String, System.String, Int32, Int32)
    0007F724 073875B9 Ironring.Management.MMC.FormNode.SetShimControl(System.Object)
    0007F738 053D9DDE Ironring.Management.MMC.FormNode.set_ControlType(System.Type)
    ...
    ...
    ...

StackTraceString: <none>
HResult: 80004005

0:014> !CLRStack
OS Thread Id: 0x11ec (14)
ESP       EIP
075af4fc 016bfd9a Ironring.Management.MMC.SnapinBase+MmcWindow.Invoke(System.Delegate, System.Object[])
...
...
...
075af740 793d87af System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)
075af748 793608fd System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
075af760 793d8898 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)
075af8f0 79e7be1b [GCFrame: 075af8f0]

!help command gives the list of other available SOS extension commands:

0:014> !help

Object Inspection

DumpObj (do)
DumpArray (da)
DumpStackObjects (dso)
DumpHeap
DumpVC
GCRoot
ObjSize
FinalizeQueue
PrintException (pe)
TraverseHeap

Examining code and stacks

Threads
CLRStack
IP2MD
U
DumpStack
EEStack
GCInfo
EHInfo
COMState
BPMD

Examining CLR data structures

DumpDomain
EEHeap
Name2EE
SyncBlk
DumpMT
DumpClass
DumpMD
Token2EE
EEVersion
DumpModule
ThreadPool
DumpAssembly
DumpMethodSig
DumpRuntimeTypes
DumpSig
RCWCleanupList
DumpIL

Diagnostic Utilities

VerifyHeap
DumpLog
FindAppDomain
SaveModule
GCHandles
GCHandleLeaks
VMMap
VMStat
ProcInfo
StopOnException (soe)
MinidumpMode

Other

FAQ

If you are new to .NET and interested in .NET debugging I would recommend 3 books:

Essential .NET, Volume I: The Common Language Runtime

Buy from Amazon

Debugging Microsoft .NET 2.0 Applications

Buy from Amazon

Advanced .NET Debugging

Buy from Amazon

Expert .NET 2.0 IL Assembler

Buy from Amazon

- Dmitry Vostokov @ DumpAnalysis.org -

COM+ crash dumps

Monday, July 16th, 2007

If you have problems with COM+ components you can configure Component Services in Control Panel to save a dump:

Refer to the following article for details:

http://msdn.microsoft.com/msdnmag/issues/01/08/ComXP/

If you want to use userdump.exe to save a crash dump when a failing COM+ application displays an error dialog box refer to the following article:

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

If you want dumps to be automatically collected after some timeout value refer to the following article for details:

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

If you have an exception the following article describes how to get a stack trace from a saved process dump:

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

This article explains how COM+ handles application faults:

Fault Isolation and Failfast Policy

Now I show how to get an error message that was written to event log when COM+ application was terminated due to a different error code than an access violation. If you get a dump from COM+ process look at all threads and find the one that runs through comsvcs.dll:

0:000> ~*k
...
...
...
6 Id: 8d4.1254 Suspend: 0 Teb: 7ffd9000 Unfrozen
ChildEBP RetAddr
0072ee30 7c822124 ntdll!KiFastSystemCallRet
0072ee34 77e6baa8 ntdll!NtWaitForSingleObject+0xc
0072eea4 77e6ba12 kernel32!WaitForSingleObjectEx+0xac
0072eeb8 75c2b250 kernel32!WaitForSingleObject+0x12
0072f340 75c2bb91 comsvcs!FF_RunCmd+0xa2
0072f60c 75c2bc76 comsvcs!FF_DumpProcess_MD+0x21a
0072f850 75c2be83 comsvcs!FF_DumpProcess+0x39
0072fdc0 75c2c351 comsvcs!FailFastStr+0x2ce
0072fe20 75bf31fa comsvcs!CError::WriteToLog+0x198
0072fe8c 75bf3d48 comsvcs!CSurrogateServices::FireApplicationLaunch+0x13b
0072fee0 75bf3e19 comsvcs!CApplication::AsyncApplicationLaunch+0x101
0072feec 7c81a3c5 comsvcs!CApplication::AppLaunchThreadProc+0x18
0072ff44 7c8200fc ntdll!RtlpWorkerCallout+0x71
0072ff64 7c81a3fa ntdll!RtlpExecuteWorkerRequest+0x4f
0072ff78 7c82017f ntdll!RtlpApcCallout+0x11
0072ffb8 77e66063 ntdll!RtlpWorkerThread+0x61
0072ffec 00000000 kernel32!BaseThreadStart+0x34
...
...
...

0:000> ~*kL
...
...
...
   6  Id: 8d4.1254 Suspend: 0 Teb: 7ffd9000 Unfrozen
ChildEBP RetAddr  Args to Child
0072ee30 7c822124 77e6baa8 00000394 00000000
ntdll!KiFastSystemCallRet
0072ee34 77e6baa8 00000394 00000000 00000000
ntdll!NtWaitForSingleObject+0xc
0072eea4 77e6ba12 00000394 ffffffff 00000000
kernel32!WaitForSingleObjectEx+0xac
0072eeb8 75c2b250 00000394 ffffffff 0072f640
kernel32!WaitForSingleObject+0x12
0072f340 75c2bb91 75b8e7fc 75b8e810 000008d4
comsvcs!FF_RunCmd+0xa2
0072f60c 75c2bc76 0072f640 75c6c5c0 0072fe44
comsvcs!FF_DumpProcess_MD+0x21a
0072f850 75c2be83 00000000 77ce21ce 0bd5f0f0
comsvcs!FF_DumpProcess+0×39
0072fdc0 75c2c351 75c6c5c0 75b8b008 00000142
comsvcs!FailFastStr+0×2ce
0072fe20 75bf31fa 0072fe44 75b8b008 00000142
comsvcs!CError::WriteToLog+0×198
0072fe8c 75bf3d48 0bcf5d0c 00000000 0bcf5cf8
comsvcs!CSurrogateServices::FireApplicationLaunch+0×13b
0072fee0 75bf3e19 75bf3e01 0072ff44 7c81a3c5
comsvcs!CApplication::AsyncApplicationLaunch+0×101
0072feec 7c81a3c5 0bcf5cf8 7c889880 0bcf5d50
comsvcs!CApplication::AppLaunchThreadProc+0×18
0072ff44 7c8200fc 75bf3e01 0bcf5cf8 00000000
ntdll!RtlpWorkerCallout+0×71
0072ff64 7c81a3fa 00000000 0bcf5cf8 0bcf5d50
ntdll!RtlpExecuteWorkerRequest+0×4f
0072ff78 7c82017f 7c8200bb 00000000 0bcf5cf8
ntdll!RtlpApcCallout+0×11
0072ffb8 77e66063 00000000 00000000 00000000
ntdll!RtlpWorkerThread+0×61
0072ffec 00000000 7c83ad38 00000000 00000000
kernel32!BaseThreadStart+0×34


FF_DumpProcess function is an indication that the process was being dumped. There is no ComSvcsExceptionFilter function on thread stack but we can still get an error message if we look at FailFastStr function arguments:

0:000> du 75c6c5c0 75c6c5c0+400
75c6c5c0  “{646F1874-46B6-4149-BD55-8C317FB”
75c6c600  “71CC0}….Server Application ID:”
75c6c640  ” {646F1874-46B6-4149-BD55-8C317F”
75c6c680  “B71CC0}..Server Application Inst”
75c6c6c0  “ance ID:..{7A39BC48-78DA-4FBB-A7″
75c6c700  “46-EEA7E42CDAC7}..Server Applica”
75c6c740  “tion Name: My Server”
75c6c780  “..The serious nature of this err”
75c6c7c0  “or has caused the process to ter”
75c6c800  “minate…Error Code = 0×80131600″
75c6c840  ” : ..COM+ Services Internals Inf”
75c6c880  “ormation:..File: d:\nt\com\compl”
75c6c8c0  “us\src\comsvcs\srgtapi\csrgtserv”
75c6c900  “.cpp, Line: 322..Comsvcs.dll fil”
75c6c940  “e version: ENU 2001.12.4720.2517″
75c6c980  ” shp”

Also if we examine parameters of FF_RunCmd call we would see what application was used to dump a process:

ChildEBP RetAddr Args to Child
0072f340 75c2bb91 75b8e7fc 75b8e810 000008d4
comsvcs!FF_RunCmd+0xa2

0:000> du 75b8e7fc
75b8e7fc  “%s %d %s”
0:000> du 75b8e810
75b8e810  “RunDll32 comsvcs.dll,MiniDump”

We can guess that the first parameter is a format string, the second one is the command line for a process dumper, the third one is PID and the fourth one should be the name of a dump file to save. We can double check this from the raw stack:

ChildEBP RetAddr Args to Child
0072f340 75c2bb91 75b8e7fc 75b8e810 000008d4
comsvcs!FF_RunCmd+0xa2

0:000> dd 0072f340
0072f340  0072f60c 75c2bb91 75b8e7fc 75b8e810
     ; saved EBP, return EIP, 1st param, 2nd param
0072f350  000008d4 0072f640 0072f84a 00000000
     ; 3rd param, 4th param

0:000> du 0072f640
0072f640  “C:\WINDOWS\system32\com\dmp\{646″
0072f680  “F1874-46B6-4149-BD55-8C317FB71CC”
0072f6c0  “0}_2007_07_16_12_05_08.dmp”

We can actually find the already formatted command that was passed to CreateProcess call on the raw stack:

0:006> du 0072ef2c
0072ef2c  "RunDll32 comsvcs.dll,MiniDump 22"
0072ef6c  "60 C:\WINDOWS\system32\com\dmp\{"
0072efac  "646F1874-46B6-4149-BD55-8C317FB7"
0072efec  "1CC0}_2007_07_16_12_05_08.dmp"

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 13b)

Sunday, July 15th, 2007

Sometimes handle leaks also result in insufficient memory especially if handles point to structures allocated by OS. Here is the typical example of the handle leak resulted in freezing several servers. The complete memory dump shows exhausted non-paged pool:

0: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:     1048352 (   4193408 Kb)
 Page File: \??\C:\pagefile.sys
   Current:   4190208 Kb  Free Space:   3749732 Kb
   Minimum:   4190208 Kb  Maximum:      4190208 Kb
 Available Pages:      697734 (   2790936 Kb)
 ResAvail Pages:       958085 (   3832340 Kb)
 Locked IO Pages:          95 (       380 Kb)
 Free System PTEs:     199971 (    799884 Kb)
 Free NP PTEs:            105 (       420 Kb)
 Free Special NP:           0 (         0 Kb)
 Modified Pages:          195 (       780 Kb)
 Modified PF Pages:       195 (       780 Kb)
 NonPagedPool Usage:    65244 (    260976 Kb)
 NonPagedPool Max:      65503 (    262012 Kb)
 ********** Excessive NonPaged Pool Usage *****

 PagedPool 0 Usage:      6576 (     26304 Kb)
 PagedPool 1 Usage:       629 (      2516 Kb)
 PagedPool 2 Usage:       624 (      2496 Kb)
 PagedPool 3 Usage:       608 (      2432 Kb)
 PagedPool 4 Usage:       625 (      2500 Kb)
 PagedPool Usage:        9062 (     36248 Kb)
 PagedPool Maximum:     66560 (    266240 Kb)

********** 184 pool allocations have failed **********

 Shared Commit:          7711 (     30844 Kb)
 Special Pool:              0 (         0 Kb)
 Shared Process:        10625 (     42500 Kb)
 PagedPool Commit:       9102 (     36408 Kb)
 Driver Commit:          1759 (      7036 Kb)
 Committed pages:      425816 (   1703264 Kb)
 Commit limit:        2052560 (   8210240 Kb)

Looking at non-paged pool consumption reveals excessive number of thread objects:

0: kd> !poolused 3
   Sorting by  NonPaged Pool Consumed

  Pool Used:
            NonPaged
 Tag    Allocs    Frees     Diff     Used
 Thre   772672   463590   309082 192867168  Thread objects , Binary: nt!ps
 MmCm       42        9       33 12153104   Calls made to MmAllocateContiguousMemory , Binary: nt!mm


The next logical step would be to list processes and find their handle usage. Indeed there is such a process:

0: kd> !process 0 0



PROCESS 88b75020  SessionId: 7  Cid: 172e4    Peb: 7ffdf000  ParentCid: 17238
    DirBase: c7fb6bc0  ObjectTable: e17f50a0  HandleCount: 143428.
    Image: iexplore.exe


Making the process current and listing its handles shows contiguously allocated handles to thread objects:

0: kd> .process 88b75020
Implicit process is now 88b75020
0: kd> .reload /user

0: kd> !handle



0d94: Object: 88a6b020  GrantedAccess: 001f03ff Entry: e35e1b28
Object: 88a6b020  Type: (8b780c68) Thread
    ObjectHeader: 88a6b008
        HandleCount: 1  PointerCount: 1

0d98: Object: 88a97320  GrantedAccess: 001f03ff Entry: e35e1b30
Object: 88a97320  Type: (8b780c68) Thread
    ObjectHeader: 88a97308
        HandleCount: 1  PointerCount: 1

0d9c: Object: 88b2b020  GrantedAccess: 001f03ff Entry: e35e1b38
Object: 88b2b020  Type: (8b780c68) Thread
    ObjectHeader: 88b2b008
        HandleCount: 1  PointerCount: 1

0da0: Object: 88b2a730  GrantedAccess: 001f03ff Entry: e35e1b40
Object: 88b2a730  Type: (8b780c68) Thread
    ObjectHeader: 88b2a718
        HandleCount: 1  PointerCount: 1

0da4: Object: 88b929a0  GrantedAccess: 001f03ff Entry: e35e1b48
Object: 88b929a0  Type: (8b780c68) Thread
    ObjectHeader: 88b92988
        HandleCount: 1  PointerCount: 1

0da8: Object: 88a57db0  GrantedAccess: 001f03ff Entry: e35e1b50
Object: 88a57db0  Type: (8b780c68) Thread
    ObjectHeader: 88a57d98
        HandleCount: 1  PointerCount: 1

0dac: Object: 88b92db0  GrantedAccess: 001f03ff Entry: e35e1b58
Object: 88b92db0  Type: (8b780c68) Thread
    ObjectHeader: 88b92d98
        HandleCount: 1  PointerCount: 1

0db0: Object: 88b4a730  GrantedAccess: 001f03ff Entry: e35e1b60
Object: 88b4a730  Type: (8b780c68) Thread
    ObjectHeader: 88b4a718
        HandleCount: 1  PointerCount: 1

0db4: Object: 88a7e730  GrantedAccess: 001f03ff Entry: e35e1b68
Object: 88a7e730  Type: (8b780c68) Thread
    ObjectHeader: 88a7e718
        HandleCount: 1  PointerCount: 1

0db8: Object: 88a349a0  GrantedAccess: 001f03ff Entry: e35e1b70
Object: 88a349a0  Type: (8b780c68) Thread
    ObjectHeader: 88a34988
        HandleCount: 1  PointerCount: 1

0dbc: Object: 88a554c0  GrantedAccess: 001f03ff Entry: e35e1b78
Object: 88a554c0  Type: (8b780c68) Thread
    ObjectHeader: 88a554a8
        HandleCount: 1  PointerCount: 1


Examination of these threads shows their stack traces and start address:

0: kd> !thread 88b4a730
THREAD 88b4a730  Cid 0004.1885c  Teb: 00000000 Win32Thread: 00000000 TERMINATED
Not impersonating
DeviceMap                 e1000930
Owning Process            8b7807a8       Image:         System
Wait Start TickCount      975361         Ticks: 980987 (0:04:15:27.921)
Context Switch Count      1
UserTime                  00:00:00.0000
KernelTime                00:00:00.0000
Start Address mydriver!StatusWaitThread (0xf5c5d128)
Stack Init 0 Current f3c4cc98 Base f3c4d000 Limit f3c4a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr  Args to Child
f3c4ccac 8083129e ffdff5f0 8697ba00 a674c913 hal!KfLowerIrql+0×62
f3c4ccc8 00000000 808ae498 8697ba00 00000000 nt!KiExitDispatcher+0×130

0: kd> !thread 88a554c0
THREAD 88a554c0  Cid 0004.1888c  Teb: 00000000 Win32Thread: 00000000 TERMINATED
Not impersonating
DeviceMap                 e1000930
Owning Process            8b7807a8       Image:         System
Wait Start TickCount      975380         Ticks: 980968 (0:04:15:27.625)
Context Switch Count      1
UserTime                  00:00:00.0000
KernelTime                00:00:00.0000
Start Address mydriver!StatusWaitThread (0xf5c5d128)
Stack Init 0 Current f3c4cc98 Base f3c4d000 Limit f3c4a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr  Args to Child
f3c4ccac 8083129e ffdff5f0 8697ba00 a674c913 hal!KfLowerIrql+0×62
f3c4ccc8 00000000 808ae498 8697ba00 00000000 nt!KiExitDispatcher+0×130

We can see that they have been terminated and their start address belongs to mydriver.sys. Therefore we can say that mydriver code has to be examined to find the source of the handle leak.

- Dmitry Vostokov @ DumpAnalysis.org -

Music for Debugging

Sunday, July 15th, 2007

Debugging and understanding multithreaded programs is hard and sometimes it requires running several execution paths mentally. Listening to composers who use multithreading in music can help here. My favourite is J.S. Bach and I recently purchased his complete works (155 CD box from Brilliant Classics). Virtuoso music helps me in live debugging too and here my favourites are Chopin and Liszt. I recently purchased 30 CD box of complete Chopin works (also from Brilliant Classics).

Many software engineers listen to music when writing code and I’m not the exception. However, I have found that not all music suitable for programming helps me during debugging sessions.

Music for relaxation, quiet classical or modern music helps me to think about program design and write solid code. Music with several melodies played simultaneously, heroic and virtuoso works help me to achieve breakthrough and find a bug. The latter kind of music also suits me for listening when doing crash dump analysis or problem troubleshooting.

In 1997 I read a wonderful book “Zen of Windows 95 Programming: Master the Art of Moving to Windows 95 and Creating High-Performance Windows Applications” written by Lou Grinzo and this book provides some music suggestions to listen to while doing programming.

Recently I’ve found one research project related to audio debugging, mapping source code to musical structures

http://www.wsu.edu/~stefika/ProgramAuralization.html

- Dmitry Vostokov @ DumpAnalysis.org -

Interrupts and exceptions explained (Part 4)

Sunday, July 15th, 2007

The previous part discussed processor interrupts in user mode. In this part I will explain WinDbg .trap command and show how to simulate it manually.

Upon an interrupt a processor saves the current instruction pointer and transfers execution to an interrupt handler as explained in the first part of these series. This interrupt handler has to save a full thread context before calling other functions to do complex interrupt processing. For example, if we disassemble KiTrap0E handler from x86 Windows 2003 crash dump we would see that it saves a lot of registers including segment registers:

3: kd> uf nt!KiTrap0E
...
...
...
nt!KiTrap0E:
e088bb2c mov     word ptr [esp+2],0
e088bb33 push    ebp
e088bb34 push    ebx
e088bb35 push    esi
e088bb36 push    edi
e088bb37 push    fs
e088bb39 mov     ebx,30h
e088bb3e mov     fs,bx
e088bb41 mov     ebx,dword ptr fs:[0]
e088bb48 push    ebx
e088bb49 sub     esp,4
e088bb4c push    eax
e088bb4d push    ecx
e088bb4e push    edx
e088bb4f push    ds
e088bb50 push    es
e088bb51 push    gs
e088bb53 mov     ax,23h
e088bb57 sub     esp,30h
e088bb5a mov     ds,ax
e088bb5d mov     es,ax
e088bb60 mov     ebp,esp
e088bb62 test    dword ptr [esp+70h],20000h
e088bb6a jne     nt!V86_kite_a (e088bb04)
...
...
...

The saved processor state information (context) forms the so called Windows kernel trap frame:

3: kd> dt _KTRAP_FRAME
+0x000 DbgEbp           : Uint4B
+0x004 DbgEip           : Uint4B
+0x008 DbgArgMark       : Uint4B
+0x00c DbgArgPointer    : Uint4B
+0x010 TempSegCs        : Uint4B
+0x014 TempEsp          : Uint4B
+0x018 Dr0              : Uint4B
+0x01c Dr1              : Uint4B
+0x020 Dr2              : Uint4B
+0x024 Dr3              : Uint4B
+0x028 Dr6              : Uint4B
+0x02c Dr7              : Uint4B
+0x030 SegGs            : Uint4B
+0x034 SegEs            : Uint4B
+0x038 SegDs            : Uint4B
+0x03c Edx              : Uint4B
+0x040 Ecx              : Uint4B
+0x044 Eax              : Uint4B
+0x048 PreviousPreviousMode : Uint4B
+0x04c ExceptionList    : Ptr32 _EXCEPTION_REGISTRATION_RECORD
+0x050 SegFs            : Uint4B
+0x054 Edi              : Uint4B
+0x058 Esi              : Uint4B
+0x05c Ebx              : Uint4B
+0x060 Ebp              : Uint4B
+0x064 ErrCode          : Uint4B
+0x068 Eip              : Uint4B
+0x06c SegCs            : Uint4B
+0x070 EFlags           : Uint4B
+0x074 HardwareEsp      : Uint4B
+0x078 HardwareSegSs    : Uint4B
+0x07c V86Es            : Uint4B
+0x080 V86Ds            : Uint4B
+0x084 V86Fs            : Uint4B
+0x088 V86Gs            : Uint4B

This Windows trap frame is not the same as an interrupt frame a processor saves on a current thread stack when an interrupt occurs in kernel mode. The latter frame is very small and consists only of EIP, CS, EFLAGS and ErrorCode. When an interrupt occurs in user mode an x86 processor additionally saves the current stack pointer SS:ESP.

The .trap command finds the trap frame on a current thread stack and sets the current thread register context using the values from that saved structure. You can see that command in action for certain bugchecks when you use !analyze -v:

3: kd> !analyze -v
KERNEL_MODE_EXCEPTION_NOT_HANDLED (8e)
...
...
...
Arguments:
Arg1: c0000005, The exception code that was not handled
Arg2: de65190c, The address that the exception occurred at
Arg3: f24f8a74, Trap Frame
Arg4: 00000000



TRAP_FRAME:  f24f8a74 — (.trap fffffffff24f8a74)
.trap fffffffff24f8a74
ErrCode = 00000000
eax=dbc128c0 ebx=dbe4a010 ecx=f24f8ac4 edx=00000001 esi=46525356 edi=00000000
eip=de65190c esp=f24f8ae8 ebp=f24f8b18 iopl=0 nv up ei pl nz na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010206
driver!foo+0×16:
de65190c 837e1c00         cmp     dword ptr [esi+1Ch],0 ds:0023:46525372=????????


If we look at the trap frame we would see the same register values that WinDbg reports above:

3: kd> dt _KTRAP_FRAME f24f8a74
+0x000 DbgEbp           : 0xf24f8b18
+0x004 DbgEip           : 0xde65190c
+0x008 DbgArgMark       : 0xbadb0d00
+0x00c DbgArgPointer    : 1
+0x010 TempSegCs        : 0xb0501cd
+0x014 TempEsp          : 0xdcc01cd0
+0x018 Dr0              : 0xf24f8aa8
+0x01c Dr1              : 0xde46c90a
+0x020 Dr2              : 0
+0x024 Dr3              : 0
+0x028 Dr6              : 0xdbe4a000
+0x02c Dr7              : 0
+0x030 SegGs            : 0
+0x034 SegEs            : 0x23
+0x038 SegDs            : 0x23
+0x03c Edx              : 1
+0x040 Ecx              : 0xf24f8ac4
+0x044 Eax              : 0xdbc128c0
+0x048 PreviousPreviousMode : 0xdbe4a010
+0x04c ExceptionList    : 0xffffffff _EXCEPTION_REGISTRATION_RECORD
+0x050 SegFs            : 0x30
+0x054 Edi              : 0
+0x058 Esi              : 0x46525356
+0x05c Ebx              : 0xdbe4a010
+0x060 Ebp              : 0xf24f8b18
+0x064 ErrCode          : 0
+0x068 Eip              : 0xde65190c ; driver!foo+0x16
+0x06c SegCs            : 8
+0x070 EFlags           : 0x10206
+0x074 HardwareEsp      : 0xdbc171b0
+0x078 HardwareSegSs    : 0xde667677
+0x07c V86Es            : 0xdbc128c0
+0x080 V86Ds            : 0xdbc171c4
+0x084 V86Fs            : 0xf24f8bc4
+0x088 V86Gs            : 0

It is good to know how to find a trap frame manually in the case the stack is corrupt or WinDbg cannot find a trap frame automatically. In this case we can take the advantage of the fact that DS and ES segment registers have the same value in the Windows flat memory model:

   +0x034 SegEs            : 0x23
+0x038 SegDs            : 0x23

We need to find 2 consecutive 0×23 values on the stack. There may be several such places but usually the correct one comes between KiTrapXX address on the stack and the initial processor trap frame shown below in red. This is because KiTrapXX obviously calls other functions to further process an interrupt so its return address is saved on the stack.

3: kd> r
eax=f535713c ebx=de65190c ecx=00000000 edx=e088e1d2 esi=f5357120 edi=00000000
eip=e0827451 esp=f24f8628 ebp=f24f8640 iopl=0 nv up ei ng nz na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00000286
nt!KeBugCheckEx+0×1b:
e0827451 5d              pop     ebp

3: kd> dds f24f8628 f24f8628+1000
...
...
...
f24f8784  de4b2995 win32k!NtUserQueryWindow
f24f8788  00000000
f24f878c  fe76a324
f24f8790  f24f8d64
f24f8794  0006e43c
f24f8798  e087c041 nt!ExReleaseResourceAndLeaveCriticalRegion+0x5
f24f879c  83f3b801
f24f87a0  f24f8a58
f24f87a4  0000003b
f24f87a8  00000000
f24f87ac  00000030
f24f87b0  00000023
f24f87b4  00000023

f24f87b8  00000000



f24f8a58  00000111
f24f8a5c  f24f8a74
f24f8a60  e088bc08 nt!KiTrap0E+0xdc
f24f8a64  00000000
f24f8a68  46525372
f24f8a6c  00000000
f24f8a70  e0889686 nt!Kei386EoiHelper+0×186
f24f8a74  f24f8b18
f24f8a78  de65190c driver!foo+0×16
f24f8a7c  badb0d00
f24f8a80  00000001
f24f8a84  0b0501cd
f24f8a88  dcc01cd0
f24f8a8c  f24f8aa8
f24f8a90  de46c90a win32k!HANDLELOCK::vLockHandle+0×80
f24f8a94  00000000
f24f8a98  00000000
f24f8a9c  dbe4a000
f24f8aa0  00000000
f24f8aa4  00000000
f24f8aa8  00000023
f24f8aac  00000023

f24f8ab0  00000001
f24f8ab4  f24f8ac4
f24f8ab8  dbc128c0
f24f8abc  dbe4a010
f24f8ac0  ffffffff
f24f8ac4  00000030
f24f8ac8  00000000
f24f8acc  46525356
f24f8ad0  dbe4a010
f24f8ad4  f24f8b18
f24f8ad8  00000000
f24f8adc  de65190c driver!foo+0×16
f24f8ae0  00000008
f24f8ae4  00010206

f24f8ae8  dbc171b0
f24f8aec  de667677 driver!bar+0×173
f24f8af0  dbc128c0
f24f8af4  dbc171c4
f24f8af8  f24f8bc4
f24f8afc  00000000


Subtracting the offset 0×38 from the address of the 00000023 value (f24f8aac) and using dt command we can check _KTRAP_FRAME structure and apply .trap command afterwards:

3: kd> dt _KTRAP_FRAME f24f8aac-38
+0x000 DbgEbp           : 0xf24f8b18
+0x004 DbgEip           : 0xde65190c
+0x008 DbgArgMark       : 0xbadb0d00
+0x00c DbgArgPointer    : 1
+0x010 TempSegCs        : 0xb0501cd
+0x014 TempEsp          : 0xdcc01cd0
+0x018 Dr0              : 0xf24f8aa8
+0x01c Dr1              : 0xde46c90a
+0x020 Dr2              : 0
+0x024 Dr3              : 0
+0x028 Dr6              : 0xdbe4a000
+0x02c Dr7              : 0
+0x030 SegGs            : 0
+0x034 SegEs            : 0x23
+0x038 SegDs            : 0x23
+0x03c Edx              : 1
+0x040 Ecx              : 0xf24f8ac4
+0x044 Eax              : 0xdbc128c0
+0x048 PreviousPreviousMode : 0xdbe4a010
+0x04c ExceptionList    : 0xffffffff _EXCEPTION_REGISTRATION_RECORD
+0x050 SegFs            : 0x30
+0x054 Edi              : 0
+0x058 Esi              : 0x46525356
+0x05c Ebx              : 0xdbe4a010
+0x060 Ebp              : 0xf24f8b18
+0x064 ErrCode          : 0
+0x068 Eip              : 0xde65190c
+0x06c SegCs            : 8
+0x070 EFlags           : 0x10206
+0x074 HardwareEsp      : 0xdbc171b0
+0x078 HardwareSegSs    : 0xde667677
+0x07c V86Es            : 0xdbc128c0
+0x080 V86Ds            : 0xdbc171c4
+0x084 V86Fs            : 0xf24f8bc4
+0x088 V86Gs            : 0

3: kd> ? f24f8aac-38
Evaluate expression: -229668236 = f24f8a74

3: kd> .trap f24f8a74
ErrCode = 00000000
eax=dbc128c0 ebx=dbe4a010 ecx=f24f8ac4 edx=00000001 esi=46525356 edi=00000000
eip=de65190c esp=f24f8ae8 ebp=f24f8b18 iopl=0 nv up ei pl nz na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010206
driver!foo+0x16:
de65190c 837e1c00        cmp     dword ptr [esi+1Ch],0 ds:0023:46525372=????????

In complete memory dumps we can see that _KTRAP_FRAME is saved when calling system services too:

3: kd> kL
ChildEBP RetAddr
f24f8ae8 de667677 driver!foo+0x16
f24f8b18 de667799 driver!bar+0x173
f24f8b90 de4a853e win32k!GreSaveScreenBits+0x69
f24f8bd8 de4922bd win32k!CreateSpb+0x167
f24f8c40 de490bb8 win32k!zzzChangeStates+0x448
f24f8c88 de4912de win32k!zzzBltValidBits+0xe2
f24f8ce0 de4926c6 win32k!xxxEndDeferWindowPosEx+0x13a
f24f8cfc de49aa8f win32k!xxxSetWindowPos+0xb1
f24f8d34 de4acf4d win32k!xxxShowWindow+0x201
f24f8d54 e0888c6c win32k!NtUserShowWindow+0x79
f24f8d54 7c94ed54 nt!KiFastCallEntry+0xfc (TrapFrame @ f24f8d64)
0006e48c 77e34f1d ntdll!KiFastSystemCallRet
0006e53c 77e2f12f USER32!NtUserShowWindow+0xc
0006e570 77e2b0fe USER32!InternalDialogBox+0xa9
0006e590 77e29005 USER32!DialogBoxIndirectParamAorW+0×37
0006e5b4 0103d569 USER32!DialogBoxParamW+0×3f
0006e5d8 0102d2f5 winlogon!Fusion_DialogBoxParam+0×24

and we can get the current thread context before its transition to kernel mode:

3: kd> .trap f24f8d64
ErrCode = 00000000
eax=7ffff000 ebx=00000000 ecx=00000000 edx=7c94ed54 esi=00532e68 edi=0002002c
eip=7c94ed54 esp=0006e490 ebp=0006e53c iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
ntdll!KiFastSystemCallRet:
001b:7c94ed54 c3              ret

3: kd> kL
ChildEBP RetAddr
0006e48c 77e34f1d ntdll!KiFastSystemCallRet
0006e53c 77e2f12f USER32!NtUserShowWindow+0xc
0006e570 77e2b0fe USER32!InternalDialogBox+0xa9
0006e590 77e29005 USER32!DialogBoxIndirectParamAorW+0x37
0006e5b4 0103d569 USER32!DialogBoxParamW+0x3f
0006e5d8 0102d2f5 winlogon!Fusion_DialogBoxParam+0x24

In the next part I’ll show an example from an x64 crash dump.

- Dmitry Vostokov @ DumpAnalysis.org -

Reading Windows-based Code (Part 1)

Friday, July 13th, 2007

As promised here is the first introductory part of the Code Reading (The Windows Perspective) training. You might need to download and install Microsoft Office Animation Runtime if you don’t have PowerPoint installed:

PowerPoint 2003/2002 Add-in: Office Animation Runtime 

The HTML version of the presentation is located here:

Reading Windows-based Code (Part 1)

- Dmitry Vostokov @ DumpAnalysis.org -

StressPrinters update

Thursday, July 12th, 2007

The new version 1.3.1 has been published and can be downloaded from Citrix technical support:

StressPrinters 1.3.1 for 32-bit and 64-bit platforms

What’s new:

  1. Configurable timeout to mark potential printer drivers in the log 

  2. The log structure and warnings are documented in the article with an example

  3. AddPrinter command line section in the article for fine-tuning tests

  4. The option to execute a post-processing command after tests 

The motivation behind the creation of this tool is explained in the previous post:

StressPrinters: Stressing Printer Autocreation 

- Dmitry Vostokov @ DumpAnalysis.org -

Troubleshooting as debugging

Wednesday, July 11th, 2007

This post is motivated by TRAFFIC steps introduced by Andreas Zeller in his book ”Why Programs Fail?”. This book is wonderful and it gives practical debugging skills coherent and solid systematical foundation.

However these steps are for fixing defects in code, the traditional view of the software debugging process. Based on an analogy with systems theories where we have different levels of abstraction like psychology, biology, chemistry and physics, I would say that debugging starts when you have the failure at the system level.

If we compare systems to applications, troubleshooting to source code debugging, the question we ask at the higher level is “Who caused the product to fail?” which also has a business and political flavor. Therefore I propose a different acronym: VERSION. If you always try to fix system problems at the code level you will get a huge “traffic” in all sense but if you troubleshoot them first you get a different system / subsystem / component version and get your problem solved faster. This is why we have technical support departments in organizations. 

There are some parallels between TRAFFIC and VERSION steps:

Track                     View the problem
Reproduce                 Environment/repro steps
Automate (and simplify)   Relevant description
Find origins              Subsystem/component
                             identification
Focus                     Identify the origin
                             (subsystem/component)
Isolate (defect in code)  Obtain the solution
                             (replace/eliminate
                              subsystem/component)
Correct (defect in code)  New case study
                             (document,
                              postmortem analysis)

Troubleshooting doesn’t eliminate the need to look at source code. In many cases a support engineer has to be proficient in code reading skill to be able to map from traces to source code. This will help in component identification, especially if your product has extensive tracing facility. I have started development of  ”Code Reading” training targeted for Windows environments and will post some presentations soon. The first one will be available tomorrow, so stay tuned.

- Dmitry Vostokov @ DumpAnalysis.org -

WinDbg is privacy-aware

Sunday, July 8th, 2007

This is a quick follow up to my previous post about privacy issues related to crash dumps. WinDbg has two options for .dump command to remove the potentially sensitive user data (from WinDbg help):

  • r  - Deletes from the minidump those portions of the stack and store memory that are not useful for recreating the stack trace. Local variables and other data type values are deleted as well. This option does not make the minidump smaller (because these memory sections are simply zeroed), but it is useful if you want to protect the privacy of other applications. 

  • R  - Deletes the full module paths from the minidump. Only the module names will be included. This is a useful option if you want to protect the privacy of the user’s directory structure.

Therefore it is possible to configure CDB or WinDbg as default postmortem debuggers and avoid process data to be included. Most of stack is zeroed except frame data pointers and return addresses used to reconstruct stack trace. Therefore string constants like passwords are eliminated. I made the following test with CDB configured as the default post-mortem debugger on my Windows x64 server:

HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\Windows NT\CurrentVersion\AeDebug
Debugger="C:\Program Files (x86)\Debugging Tools for Windows\cdb.exe" -p %ld -e %ld -g -c ".dump /o /mrR /u c:\temp\safedump.dmp; q"

I got the following stack trace from TestDefaultDebugger (module names and function offsets are removed for visual clarity):

0:000> kvL 100
ChildEBP RetAddr  Args to Child
002df868 00403263 00425ae8 00000000 002df8a8 OnBnClickedButton1
002df878 00403470 002dfe90 00000000 00000000 _AfxDispatchCmdMsg
002df8a8 00402a27 00000000 00000000 00000000 OnCmdMsg
002df8cc 00408e69 00000000 00000000 00000000 OnCmdMsg
002df91c 004098d9 00000000 00580a9e 00000000 OnCommand
002df9b8 00406258 00000000 00000000 00580a9e OnWndMsg
002df9d8 0040836d 00000000 00000000 00580a9e WindowProc
002dfa40 004083f4 00000000 00000000 00000000 AfxCallWndProc
002dfa60 7d9472d8 00000000 00000000 00000000 AfxWndProc
002dfa8c 7d9475c3 004083c0 00000000 00000000 InternalCallWinProc
002dfb04 7d948626 00000000 004083c0 00000000 UserCallWinProcCheckWow
002dfb48 7d94868d 00000000 00000000 00000000 SendMessageWorker
002dfb6c 7dbf87b3 00000000 00000000 00000000 SendMessageW
002dfb8c 7dbf8895 00000000 00000000 00000000 Button_NotifyParent
002dfba8 7dbfab9a 00000000 00000000 002dfcb0 Button_ReleaseCapture
002dfc38 7d9472d8 00580a9e 00000000 00000000 Button_WndProc
002dfc64 7d9475c3 7dbfa313 00580a9e 00000000 InternalCallWinProc
002dfcdc 7d9477f6 00000000 7dbfa313 00580a9e UserCallWinProcCheckWow
002dfd54 7d947838 00000000 00000000 002dfd90 DispatchMessageWorker
002dfd64 7d956ca0 00000000 00000000 002dfe90 DispatchMessageW
002dfd90 0040568b 00000000 00000000 002dfe90 IsDialogMessageW
002dfda0 004065d8 00000000 00402a07 00000000 IsDialogMessageW
002dfda8 00402a07 00000000 00000000 00000000 PreTranslateInput
002dfdb8 00408041 00000000 00000000 002dfe90 PreTranslateMessage
002dfdc8 00403ae3 00000000 00000000 00000000 WalkPreTranslateTree
002dfddc 00403c1e 00000000 00403b29 00000000 AfxInternalPreTranslateMessage
002dfde4 00403b29 00000000 00403c68 00000000 PreTranslateMessage
002dfdec 00403c68 00000000 00000000 002dfe90 AfxPreTranslateMessage
002dfdfc 00407920 00000000 002dfe90 002dfe6c AfxInternalPumpMessage
002dfe20 004030a1 00000000 00000000 0042ec18 CWnd::RunModalLoop
002dfe6c 0040110d 00000000 0042ec18 0042ec18 CDialog::DoModal
002dff18 004206fb 00000000 00000000 00000000 InitInstance
002dff28 0040e852 00400000 00000000 00000000 AfxWinMain
002dffc0 7d4e992a 00000000 00000000 00000000 __tmainCRTStartup
002dfff0 00000000 0040e8bb 00000000 00000000 BaseProcessStart

We can see that most arguments are zeroes. Those that are not either do not point to valid data or related to function return addresses and frame pointers. This can be seen from the raw stack data as well:

0:000> dds esp
002df86c  00403263 TestDefaultDebugger!_AfxDispatchCmdMsg+0x43
002df870  00425ae8 TestDefaultDebugger!CTestDefaultDebuggerApp::`vftable'+0x154
002df874  00000000
002df878  002df8a8
002df87c  00403470 TestDefaultDebugger!CCmdTarget::OnCmdMsg+0x118
002df880  002dfe90
002df884  00000000
002df888  00000000
002df88c  004014f0 TestDefaultDebugger!CTestDefaultDebuggerDlg::OnBnClickedButton1
002df890  00000000
002df894  00000000
002df898  00000000
002df89c  002dfe90
002df8a0  00000000
002df8a4  00000000
002df8a8  002df8cc
002df8ac  00402a27 TestDefaultDebugger!CDialog::OnCmdMsg+0x1b
002df8b0  00000000
002df8b4  00000000
002df8b8  00000000
002df8bc  00000000
002df8c0  00000000
002df8c4  002dfe90
002df8c8  00000000
002df8cc  002df91c
002df8d0  00408e69 TestDefaultDebugger!CWnd::OnCommand+0x90
002df8d4  00000000
002df8d8  00000000
002df8dc  00000000
002df8e0  00000000
002df8e4  002dfe90
002df8e8  002dfe90

We can compare it with the normal full or minidump saved with other /m options. The data zeroed when we use /mr option is shown in red color (module names and function offsets are removed for visual clarity):

0:000> kvL 100
ChildEBP RetAddr Args to Child
002df868 00403263 00425ae8 00000111 002df8a8 OnBnClickedButton1
002df878 00403470 002dfe90 000003e8 00000000 _AfxDispatchCmdMsg
002df8a8 00402a27 000003e8 00000000 00000000 OnCmdMsg
002df8cc 00408e69 000003e8 00000000 00000000 OnCmdMsg
002df91c 004098d9 00000000 00271876 d5b6c7f7 OnCommand
002df9b8 00406258 00000111 000003e8 00271876 OnWndMsg
002df9d8 0040836d 00000111 000003e8 00271876 WindowProc
002dfa40 004083f4 00000000 00561878 00000111 AfxCallWndProc
002dfa60 7d9472d8 00561878 00000111 000003e8 AfxWndProc
002dfa8c 7d9475c3 004083c0 00561878 00000111 InternalCallWinProc
002dfb04 7d948626 00000000 004083c0 00561878 UserCallWinProcCheckWow
002dfb48 7d94868d 00aec860 00000000 00000111 SendMessageWorker
002dfb6c 7dbf87b3 00561878 00000111 000003e8 SendMessageW
002dfb8c 7dbf8895 002ec9e0 00000000 0023002c Button_NotifyParent
002dfba8 7dbfab9a 002ec9e0 00000001 002dfcb0 Button_ReleaseCapture
002dfc38 7d9472d8 00271876 00000202 00000000 Button_WndProc
002dfc64 7d9475c3 7dbfa313 00271876 00000202 InternalCallWinProc
002dfcdc 7d9477f6 00000000 7dbfa313 00271876 UserCallWinProcCheckWow
002dfd54 7d947838 002e77f8 00000000 002dfd90 DispatchMessageWorker
002dfd64 7d956ca0 002e77f8 00000000 002dfe90 DispatchMessageW
002dfd90 0040568b 00561878 00000000 002dfe90 IsDialogMessageW
002dfda0 004065d8 002e77f8 00402a07 002e77f8 IsDialogMessageW
002dfda8 00402a07 002e77f8 002e77f8 00561878 PreTranslateInput
002dfdb8 00408041 002e77f8 002e77f8 002dfe90 PreTranslateMessage
002dfdc8 00403ae3 00561878 002e77f8 002e77f8 WalkPreTranslateTree
002dfddc 00403c1e 002e77f8 00403b29 002e77f8 AfxInternalPreTranslateMessage
002dfde4 00403b29 002e77f8 00403c68 002e77f8 PreTranslateMessage
002dfdec 00403c68 002e77f8 00000000 002dfe90 AfxPreTranslateMessage
002dfdfc 00407920 00000004 002dfe90 002dfe6c AfxInternalPumpMessage
002dfe20 004030a1 00000004 d5b6c023 0042ec18 RunModalLoop
002dfe6c 0040110d d5b6c037 0042ec18 0042ec18 DoModal
002dff18 004206fb 00000ece 00000002 00000001 InitInstance
002dff28 0040e852 00400000 00000000 001d083e AfxWinMain
002dffc0 7d4e992a 00000000 00000000 7efdf000 __tmainCRTStartup
002dfff0 00000000 0040e8bb 00000000 000000c8 BaseProcessStart

0:000> dds esp
002df86c 00403263 TestDefaultDebugger!_AfxDispatchCmdMsg+0x43
002df870 00425ae8 TestDefaultDebugger!CTestDefaultDebuggerApp::`vftable'+0x154
002df874 00000111
002df878 002df8a8
002df87c 00403470 TestDefaultDebugger!CCmdTarget::OnCmdMsg+0×118
002df880 002dfe90
002df884 000003e8
002df888 00000000
002df88c 004014f0 TestDefaultDebugger!CTestDefaultDebuggerDlg::OnBnClickedButton1
002df890 00000000
002df894 00000038
002df898 00000000
002df89c 002dfe90
002df8a0 000003e8
002df8a4 00000000
002df8a8 002df8cc
002df8ac 00402a27 TestDefaultDebugger!CDialog::OnCmdMsg+0×1b
002df8b0 000003e8
002df8b4 00000000
002df8b8 00000000
002df8bc 00000000
002df8c0 000003e8
002df8c4 002dfe90
002df8c8 00000000
002df8cc 002df91c
002df8d0 00408e69 TestDefaultDebugger!CWnd::OnCommand+0×90
002df8d4 000003e8
002df8d8 00000000
002df8dc 00000000
002df8e0 00000000
002df8e4 002dfe90
002df8e8 002dfe90

- Dmitry Vostokov @ DumpAnalysis.org -

WinDbg update 6.7.5.1

Sunday, July 8th, 2007

The new WinDbg has been released this week: 6.7.5.1. Contains some enhancements since 6.7.5.0 released earlier in April.

What’s New for Debugging Tools for Windows

One improvement is for handling mini-dumps:

When loading modules from a user-mode minidump provide available misc and CV record info from dump. This can allow symbols to be loaded in some cases when PE image file is not available.

- Dmitry Vostokov @ DumpAnalysis.org -