Software Diagnostics Library

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

As soon as I dug out the 3rd edition of this book to download samples for my internal projects I found that the new edition was published this month! I read all of them and now ordering the 4th edition:

Windows System Programming (4th Edition)

Actually I re-read the 2nd edition of Johnson M. Hart’s book when looking for a job in 2003 and coupled with timely reading of John Robbings’ book Debugging Applications (1st 2000 edition) secured my landing in Dublin East Point Business Park.

This book is an essential reading for Windows memory dump analysts, software maintenance and escalation engineers, software defect researchers and software tool developers. It lucidly describes and succinctly illustrates user-land Windows API with practical console mode samples in plain C. This book is especially valuable for software engineers coming from UNIX background because the author draws various parallels and provides maps between UNIX / Pthreads and Win32 / 64 APIs. Highly recommended! Plan to post an Amazon review when I get the copy of the 4th edition.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

For certain stack traces we should always be aware of Coincidental Frames similar to Coincidental Symbolic Information pattern for raw stack data. Such frames can lead to a wrong analysis conclusion. Consider this stack trace fragment from a kernel memory dump:

0: kd> kL 100
ChildEBP RetAddr
9c5b6550 8082d9a4 nt!KeBugCheckEx+0×1b
9c5b6914 8088befa nt!KiDispatchException+0×3a2
9c5b697c 8088beae nt!CommonDispatchException+0×4a
9c5b699c 80a6056d nt!KiExceptionExit+0×186
9c5b69a0 80893ae2 hal!KeReleaseQueuedSpinLock+0×2d
9c5b6a08 b20c3de5 nt!MiFreePoolPages+0×7dc
WARNING: Stack unwind information not available. Following frames may be wrong.
9c5b6a48 b20c4107 DeriverA+0×17de5
[…]

The frame with MiFreePoolPages symbol might suggest some sort of a pool corruption. We can even double check return addresses and see the valid common sense assembly language code:

0: kd> ub 8088beae
nt!KiExceptionExit+0×167:
8088be8f 33c9            xor     ecx,ecx
8088be91 e81a000000      call    nt!CommonDispatchException (8088beb0)
8088be96 33d2            xor     edx,edx
8088be98 b901000000      mov     ecx,1
8088be9d e80e000000      call    nt!CommonDispatchException (8088beb0)
8088bea2 33d2            xor     edx,edx
8088bea4 b902000000      mov     ecx,2
8088bea9 e802000000      call    nt!CommonDispatchException (8088beb0)

0: kd> ub 80a6056d
hal!KeReleaseQueuedSpinLock+0×1b:
80a6055b 7511            jne     hal!KeReleaseQueuedSpinLock+0×2e (80a6056e)
80a6055d 50              push    eax
80a6055e f00fb119        lock cmpxchg dword ptr [ecx],ebx
80a60562 58              pop     eax
80a60563 7512            jne     hal!KeReleaseQueuedSpinLock+0×37 (80a60577)
80a60565 5b              pop     ebx
80a60566 8aca            mov     cl,dl
80a60568 e8871e0000      call    hal!KfLowerIrql (80a623f4)

0: kd> ub 80893ae2
nt!MiFreePoolPages+0×7c3:
80893ac9 761c            jbe     nt!MiFreePoolPages+0×7e1 (80893ae7)
80893acb ff75f8          push    dword ptr [ebp-8]
80893ace ff7508          push    dword ptr [ebp+8]
80893ad1 e87ea1fcff      call    nt!MiFreeNonPagedPool (8085dc54)
80893ad6 8a55ff          mov     dl,byte ptr [ebp-1]
80893ad9 6a0f            push    0Fh
80893adb 59              pop     ecx
80893adc ff1524118080    call    dword ptr [nt!_imp_KeReleaseQueuedSpinLock (80801124)]

0: kd> ub b20c3de5
DriverA+0×17dcf:
b20c3dcf 51              push    ecx
b20c3dd0 ff5010          call    dword ptr [eax+10h]
b20c3dd3 eb10            jmp     DriverA+0×17de5 (b20c3de5)
b20c3dd5 8b5508          mov     edx,dword ptr [ebp+8]
b20c3dd8 52              push    edx
b20c3dd9 8d86a0000000    lea     eax,[esi+0A0h]
b20c3ddf 50              push    eax
b20c3de0 e8ebf1ffff      call    DriverA+0×16fd0 (b20c2fd0)

However, if we try to reconstruct the stack trace manually we would naturally skip these 3 frames (shown in magenta):

9c5b6550 8082d9a4 nt!KeBugCheckEx+0x1b
9c5b6914 8088befa nt!KiDispatchException+0x3a2
9c5b697c 8088beae nt!CommonDispatchException+0x4a
9c5b699c 80a6056d nt!KiExceptionExit+0×186
9c5b69a0 80893ae2 hal!KeReleaseQueuedSpinLock+0×2d
9c5b6a08 b20c3de5 nt!MiFreePoolPages+0×7dc
9c5b6a48 b20c4107 DeriverA+0×17de5
[…]

0: kd> !thread
THREAD 8f277020  Cid 081c.7298  Teb: 7ff11000 Win32Thread: 00000000 RUNNING on processor 0
IRP List:
8e234b60: (0006,0094) Flags: 00000000  Mdl: 00000000
Not impersonating
DeviceMap                 e1002880
Owning Process            8fc78b80       Image:         ProcessA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      49046879       Ticks: 0
Context Switch Count      10
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address DllA!ThreadA (0x7654dc90)
Start Address kernel32!BaseThreadStartThunk (0x77e617dc)
Stack Init 9c5b7000 Current 9c5b6c50 Base 9c5b7000 Limit 9c5b4000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr  Args to Child
[…]

0: kd> dds 9c5b4000 9c5b7000
9c5b4000  00000000
9c5b4004  00000000
9c5b4008  00000000
[...]
9c5b6290  ffdff13c
9c5b6294  9c5b6550
9c5b6298  80827e01 nt!KeBugCheckEx+0×1b
9c5b629c  00000008
9c5b62a0  00000286
[…]
9c5b654c  00000000
9c5b6550  9c5b6914
9c5b6554  8082d9a4 nt!KiDispatchException+0×3a2
9c5b6558  0000008e
9c5b655c  c0000005
[…]
9c5b6910  ffffffff
9c5b6914  9c5b6984
9c5b6918  8088befa nt!CommonDispatchException+0×4a
9c5b691c  9c5b6930
9c5b6920  00000000
[…]
9c5b6980  8088beae nt!KiExceptionExit+0×186
9c5b6984  9c5b6a08
9c5b6988  b20c3032 DriverA+0×17032
9c5b698c  badb0d00
9c5b6990  00000006
9c5b6994  8dc11cec
9c5b6998  808b6900 nt!KiTimerTableLock+0×3c0
9c5b699c  9c5b69d4
9c5b69a0  80a6056d hal!KeReleaseQueuedSpinLock+0×2d
9c5b69a4  80893ae2 nt!MiFreePoolPages+0×7dc
9c5b69a8  808b0b40 nt!NonPagedPoolDescriptor
9c5b69ac  03151fd0
9c5b69b0  00000000
9c5b69b4  00000000
[…]
9c5b6a04  8f47123b
9c5b6a08  9c5b6a48
9c5b6a0c  b20c3de5 DriverA+0×17de5
9c5b6a10  8e3640a0
9c5b6a14  8f4710d0
[…]
9c5b6a44  00000000
9c5b6a48  9c5b6a80
9c5b6a4c  b20c4107 DriverA+0×18107
9c5b6a50  8f4710d0
9c5b6a54  9c5b6a6c
[…]

If we try to find a pointer to the exception record we get this crash address:

0: kd> .exr 9c5b6930
ExceptionAddress: b20c3032 (DriverA+0×00017032)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000000
Parameter[1]: 00000157
Attempt to read from address 00000157

If we disassemble it we see an inlined string or memory copy, perhaps wcscpy function:

0: kd> u b20c3032
DriverA+0×17032:
b20c3032 f3a5            rep movs dword ptr es:[edi],dword ptr [esi]
b20c3034 8bcb            mov     ecx,ebx
b20c3036 83e103          and     ecx,3
b20c3039 f3a4            rep movs byte ptr es:[edi],byte ptr [esi]
b20c303b 8b750c          mov     esi,dword ptr [ebp+0Ch]
b20c303e 0fb7ca          movzx   ecx,dx
b20c3041 894e14          mov     dword ptr [esi+14h],ecx
b20c3044 8b700c          mov     esi,dword ptr [eax+0Ch]

So the problem happened in DriverA code, not in MiFreePoolPages or KeReleaseQueuedSpinLock.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

This post is not about debugging a computer bus. It is about debugging on a bus. More correctly, it is about debugging software running on a bus, not on a computer bus but on a real bus. A few days ago I was on a bus leaving Dublin bus station to Dublin airport. Looking around inside the bus I noticed one monitor had a characteristic Windows XP-style message box of an access violation. It was just before disembarking the bus so I made a mental effort to memorize the referenced memory address: 0×4000 and the instruction address: x73f18a09. The application name was bb.exe. Google search for 73f10000 module load address points to this one:

ModLoad: 73f10000 73f6c000   C:\WINDOWS\system32\DSOUND.dll

Not really a debugging (there’s no fix from me) so it can be named as a bus analysis exercise.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Reinterpreting Mr. Sherlock Holmes’ words (as heard by Dr. Watson) in this zero-paradigmatic (no word substitution) semantic suffixal bugtation:

“Stop, driver, stop!” Did he forget a stop code?

Sherlock Holmes, A Study in Scarlet, Part 1, 3: The Lauriston Gardens Mystery

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Here we show an example of a wait chain involving process objects. This Wait Chain pattern variation is similar to threads waiting for thread objects. When looking at stack trace collection from a complete memory dump file we see several threads in a set of processes are blocked in ALPC wait chain:

THREAD fffffa80110b8700  Cid 12f8.1328  Teb: 000000007ef9a000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable
    fffffa80110b8a90  Semaphore Limit 0x1
Waiting for reply to ALPC Message fffff8801c7096e0 : queued at port fffffa8010c9d9a0 : owned by process fffffa80109c8c10
Not impersonating
DeviceMap                 fffff880097ce5e0
Owning Process            fffffa80110ad510       Image:         ProcessA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      14004580       Ticks: 62149 (0:00:16:09.530)
Context Switch Count      25100            
UserTime                  00:00:00.421
KernelTime                00:00:00.218
Win32 Start Address 0×0000000074ca29e1
Stack Init fffffa6003bc4db0 Current fffffa6003bc4670
Base fffffa6003bc5000 Limit fffffa6003bbf000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffffa60`03bc46b0 fffff800`01cba0fa nt!KiSwapContext+0×7f
fffffa60`03bc47f0 fffff800`01caedab nt!KiSwapThread+0×13a
fffffa60`03bc4860 fffff800`01ce4e72 nt!KeWaitForSingleObject+0×2cb
fffffa60`03bc48f0 fffff800`01f32f34 nt!AlpcpSignalAndWait+0×92
fffffa60`03bc4980 fffff800`01f2f9c6 nt!AlpcpReceiveSynchronousReply+0×44
fffffa60`03bc49e0 fffff800`01f1f52f nt!AlpcpProcessSynchronousRequest+0×24f
fffffa60`03bc4b00 fffff800`01cb7973 nt!NtAlpcSendWaitReceivePort+0×19f
fffffa60`03bc4bb0 00000000`7713756a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`03bc4c20)
00000000`016ee5b8 00000000`74f9993f ntdll!ZwAlpcSendWaitReceivePort+0xa
00000000`016ee5c0 00000000`74f8a996 wow64!whNtAlpcSendWaitReceivePort+0×5f
00000000`016ee610 00000000`75183688 wow64!Wow64SystemServiceEx+0xca
00000000`016eeec0 00000000`74f8ab46 wow64cpu!ServiceNoTurbo+0×28
00000000`016eef50 00000000`74f8a14c wow64!RunCpuSimulation+0xa
00000000`016eef80 00000000`771605a8 wow64!Wow64LdrpInitialize+0×4b4
00000000`016ef4e0 00000000`771168de ntdll! ?? ::FNODOBFM::`string’+0×20aa1
00000000`016ef590 00000000`00000000 ntdll!LdrInitializeThunk+0xe

1: kd> !alpc /m fffff8801c7096e0

Message @ fffff8801c7096e0
  MessageID             : 0x263C (9788)
  CallbackID            : 0x29F2A02 (43985410)
  SequenceNumber        : 0x000009FE (2558)
  Type                  : LPC_REQUEST
  DataLength            : 0x0058 (88)
  TotalLength           : 0x0080 (128)
  Canceled              : No
  Release               : No
  ReplyWaitReply        : No
  Continuation          : Yes
  OwnerPort             : fffffa8015128040 [ALPC_CLIENT_COMMUNICATION_PORT]
  WaitingThread         : fffffa80110b8700
  QueueType             : ALPC_MSGQUEUE_PENDING
  QueuePort             : fffffa8010c9d9a0 [ALPC_CONNECTION_PORT]
  QueuePortOwnerProcess : fffffa80109c8c10 (ProcessB.exe)
  ServerThread          : fffffa8013b87bb0
  QuotaCharged          : No
  CancelQueuePort       : 0000000000000000
  CancelSequencePort    : 0000000000000000
  CancelSequenceNumber  : 0×00000000 (0)
  ClientContext         : 0000000009b49208
  ServerContext         : 0000000000000000
  PortContext           : 000000000280f0d0
  CancelPortContext     : 0000000000000000
  SecurityData          : 0000000000000000
  View                  : 0000000000000000

If we look at process fffffa80109c8c10 and its thread fffffa8013b87bb0 we would see that it is blocked as well on some kind of a lock:

THREAD fffffa8013b87bb0  Cid 0358.2c60  Teb: 000007fffff7e000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
    fffffa8010bca370  Semaphore Limit 0x7fffffff
    fffffa8013b87c68  NotificationTimer
Impersonation token:  fffff8801e614060 (Level Impersonation)
DeviceMap                 fffff880097ce5e0
Owning Process            fffffa80109c8c10       Image:         ProcessB.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      14004580       Ticks: 62149 (0:00:16:09.530)
Context Switch Count      134            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address RPCRT4!ThreadStartRoutine (0x000007feff267780)
Stack Init fffffa6035a1fdb0 Current fffffa6035a1f940
Base fffffa6035a20000 Limit fffffa6035a1a000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffffa60`35a1f980 fffff800`01cba0fa nt!KiSwapContext+0x7f
fffffa60`35a1fac0 fffff800`01caedab nt!KiSwapThread+0x13a
fffffa60`35a1fb30 fffff800`01f1d608 nt!KeWaitForSingleObject+0x2cb
fffffa60`35a1fbc0 fffff800`01cb7973 nt!NtWaitForSingleObject+0x98
fffffa60`35a1fc20 00000000`77136d5a nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa60`35a1fc20)
00000000`0486ec28 00000000`770f559f ntdll!ZwWaitForSingleObject+0xa
00000000`0486ec30 00000000`ff77d4e9 ntdll!RtlAcquireResourceShared+0xd1
00000000`0486ec70 00000000`ff77fb4d ProcessB!CLock::CLock+0×61
[…]
00000000`0486eee0 000007fe`ff261f46 RPCRT4!Invoke+0×65
00000000`0486ef40 000007fe`ff26254d RPCRT4!NdrStubCall2+0×348
00000000`0486f520 000007fe`ff2868d4 RPCRT4!NdrServerCall2+0×1d
00000000`0486f550 000007fe`ff2869f0 RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`0486f580 000007fe`ff287402 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×100
00000000`0486f670 000007fe`ff287080 RPCRT4!LRPC_SCALL::DispatchRequest+0×1c2
00000000`0486f6e0 000007fe`ff2862bb RPCRT4!LRPC_SCALL::HandleRequest+0×200
00000000`0486f800 000007fe`ff285e1a RPCRT4!LRPC_ADDRESS::ProcessIO+0×44a
00000000`0486f920 000007fe`ff267769 RPCRT4!LOADABLE_TRANSPORT::ProcessIOEvents+0×24a
00000000`0486f9d0 000007fe`ff267714 RPCRT4!ProcessIOEventsWrapper+0×9
00000000`0486fa00 000007fe`ff2677a4 RPCRT4!BaseCachedThreadRoutine+0×94
00000000`0486fa40 00000000`76fdbe3d RPCRT4!ThreadStartRoutine+0×24
00000000`0486fa70 00000000`77116a51 kernel32!BaseThreadInitThunk+0xd
00000000`0486faa0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

There are many such threads and inspection of all threads in the process fffffa80109c8c10 reveals another thread waiting for an ALPC reply:

THREAD fffffa8010c9b060  Cid 0358.02ac  Teb: 000007fffffd3000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable
    fffffa8010c9b3f0  Semaphore Limit 0x1
    Waiting for reply to ALPC Message fffff88011994cf0 : queued at port fffffa8010840360 : owned by process fffffa801083e120
Not impersonating
DeviceMap                 fffff880000073d0
Owning Process            fffffa80109c8c10       Image:         ProcessB.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      13986969       Ticks: 79760 (0:00:20:44.263)
Context Switch Count      712            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address ntdll!TppWorkerThread (0×0000000077107cb0)
Stack Init fffffa6004bfbdb0 Current fffffa6004bfb670
Base fffffa6004bfc000 Limit fffffa6004bf6000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP          RetAddr           Call Site
fffffa60`04bfb6b0 fffff800`01cba0fa nt!KiSwapContext+0×7f
fffffa60`04bfb7f0 fffff800`01caedab nt!KiSwapThread+0×13a
fffffa60`04bfb860 fffff800`01ce4e72 nt!KeWaitForSingleObject+0×2cb
fffffa60`04bfb8f0 fffff800`01f32f34 nt!AlpcpSignalAndWait+0×92
fffffa60`04bfb980 fffff800`01f2f9c6 nt!AlpcpReceiveSynchronousReply+0×44
fffffa60`04bfb9e0 fffff800`01f1f52f nt!AlpcpProcessSynchronousRequest+0×24f
fffffa60`04bfbb00 fffff800`01cb7973 nt!NtAlpcSendWaitReceivePort+0×19f
fffffa60`04bfbbb0 00000000`7713756a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`04bfbc20)
00000000`00c3f2f8 00000000`771872c9 ntdll!ZwAlpcSendWaitReceivePort+0xa
[…]
00000000`00c3f810 00000000`77107fd0 ntdll!RtlpTpWorkCallback+0xf2
00000000`00c3f8c0 00000000`76fdbe3d ntdll!TppWorkerThread+0×3d6
00000000`00c3fb40 00000000`77116a51 kernel32!BaseThreadInitThunk+0xd
00000000`00c3fb70 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

1: kd> !alpc /m fffff88011994cf0

Message @ fffff88011994cf0
  MessageID             : 0x033C (828)
  CallbackID            : 0x29CEF57 (43839319)
  SequenceNumber        : 0x000000D8 (216)
  Type                  : LPC_REQUEST
  DataLength            : 0x000C (12)
  TotalLength           : 0x0034 (52)
  Canceled              : No
  Release               : No
  ReplyWaitReply        : No
  Continuation          : Yes
  OwnerPort             : fffffa8010c99040 [ALPC_CLIENT_COMMUNICATION_PORT]
  WaitingThread         : fffffa8010c9b060
  QueueType             : ALPC_MSGQUEUE_PENDING
  QueuePort             : fffffa8010840360 [ALPC_CONNECTION_PORT]
  QueuePortOwnerProcess : fffffa801083e120 (ProcessC.exe)
  ServerThread          : fffffa80109837d0
  QuotaCharged          : No
  CancelQueuePort       : 0000000000000000
  CancelSequencePort    : 0000000000000000
  CancelSequenceNumber  : 0×00000000 (0)
  ClientContext         : 0000000000000000
  ServerContext         : 0000000000000000
  PortContext           : 00000000005f3400
  CancelPortContext     : 0000000000000000
  SecurityData          : 0000000000000000
  View                  : 0000000000000000

We see that ProcessC thread fffffa80109837d0 is waiting for a process object fffffa801434cb40:

THREAD fffffa80109837d0  Cid 027c.02b0  Teb: 000007fffffdb000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
    fffffa801434cb40  ProcessObject
Not impersonating
DeviceMap                 fffff880000073d0
Owning Process            fffffa801083e120       Image:         ProcessC.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      13986969       Ticks: 79760 (0:00:20:44.263)
Context Switch Count      520            
UserTime                  00:00:00.000
KernelTime                00:00:00.062
Win32 Start Address 0×000000004826dcf4
Stack Init fffffa6002547db0 Current fffffa6002547940
Base fffffa6002548000 Limit fffffa6002542000 Call 0
Priority 13 BasePriority 11 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP          RetAddr           Call Site
fffffa60`02547980 fffff800`01cba0fa nt!KiSwapContext+0×7f
fffffa60`02547ac0 fffff800`01caedab nt!KiSwapThread+0×13a
fffffa60`02547b30 fffff800`01f1d608 nt!KeWaitForSingleObject+0×2cb
fffffa60`02547bc0 fffff800`01cb7973 nt!NtWaitForSingleObject+0×98
fffffa60`02547c20 00000000`77136d5a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`02547c20)
00000000`0024f7c8 00000000`4826ea97 ntdll!ZwWaitForSingleObject+0xa
00000000`0024f7d0 00000000`4826ef44 ProcessC!TerminatePID+0xa3
[…]
00000000`0024fc90 00000000`00000000 ntdll!RtlUserThreadStart+0×29

When we inspect process fffffa801434cb40 we see that it has only one thread with many usual threads missing. The blocked thread stack trace has DriverA module code waiting for an event:

1: kd> !process fffffa801434cb40 ff
PROCESS fffffa801434cb40
    SessionId: 1  Cid: a0c8    Peb: 7fffffdc000  ParentCid: 1c08
    DirBase: 19c6cc000  ObjectTable: fffff8801767ee00  HandleCount: 287.
    Image: ProcessD.exe
    VadRoot fffffa8021be17d0 Vads 71 Clone 0 Private 955. Modified 1245. Locked 0.
    DeviceMap fffff880000073d0
    Token                             fffff880187cb3c0
    ElapsedTime                       00:49:23.432
    UserTime                          00:00:00.686
    KernelTime                        00:00:00.904
    QuotaPoolUsage[PagedPool]         208080
    QuotaPoolUsage[NonPagedPool]      6720
    Working Set Sizes (now,min,max)  (2620, 50, 345) (10480KB, 200KB, 1380KB)
    PeakWorkingSetSize                3136
    VirtualSize                       101 Mb
    PeakVirtualSize                   222 Mb
    PageFaultCount                    13495
    MemoryPriority                    BACKGROUND
    BasePriority                      13
    CommitCharge                      1154

[...]

THREAD fffffa8012249b30  Cid a0c8.31b4  Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
   fffffa801180a6a0  SynchronizationEvent
   Not impersonating
DeviceMap                 fffff880000073d0
Owning Process            fffffa801434cb40       Image:         ProcessD.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      13986969       Ticks: 79760 (0:00:20:44.263)
Context Switch Count      97            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address DllA (0xfffff96000eeada0)
Stack Init fffffa601b841db0 Current fffffa601b841960
Base fffffa601b842000 Limit fffffa601b83c000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffffa60`1b8419a0 fffff800`01cba0fa nt!KiSwapContext+0x7f
fffffa60`1b841ae0 fffff800`01caedab nt!KiSwapThread+0x13a
fffffa60`1b841b50 fffff960`00eeb281 nt!KeWaitForSingleObject+0x2cb
fffffa60`1b841c20 fffff800`01ec7bc7 DriverA+0×4b281
fffffa60`1b841d50 fffff800`01cf65a6 nt!PspSystemThreadStartup+0×57
fffffa60`1b841d80 00000000`00000000 nt!KiStartSystemThread+0×16

We therefore recommend to contact the vendor of DriverA component.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Gorgon Medusa is a freezing device saving a memory dump of a process or a system with the aim to achieve its immortality. A mirror used by Perseus is a better memory capturing device (or a debugger) that allowed him to inspect the freezing device non-invasively.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Thanks to everyone who submitted their debugger logs. Now VBScript and WinDbg script files are available for download from the CARE page:

http://www.dumpanalysis.org/care

VBScript file scans all hard drives for .DMP files and launches WinDbg to run a mode-independent WinDbg script. Each instance of WinDbg appends the output to dbgeng.log file that you can submit to CARE (please zip it if exceeds 2Mb).

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Another useful pattern is called Time Delta. This is a time interval between significant events. For example,

#     Module PID  TID  Time         File    Function Message
1                      10:06:18.994                  (Start)
[...]
6060  dllA   1604 7108 10:06:21.746 fileA.c DllMain  DLL_PROCESS_ATTACH
[…]
24480 dllA   1604 7108 10:06:32.262 fileA.c Exec     Path: C:\Program Files\CompanyA\appB.exe
[…]
24550 dllB   1604 9588 10:06:32.362 fileB.c PostMsg  Event Q
[…]
28230                  10:07:05.170                  (End)

Such deltas are useful in examining delays. In the trace fragment above we are interested in dllA activity from its load until it launches appB.exe. We see that the time delta was only 10 seconds. The message #24550 was the last message from the process ID 1604 and after that we didn’t “hear” from that PID for more than 30 seconds until the tracing was stopped.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

When looking at software traces and doing either a search for or just scrolling certain messages have our attention immediately. We call them Significant Events and hence the name of this pattern, Significant Event. It could be a recorded exception or an error, a basic fact, a trace message from vocabulary index, or just any trace statement that marks the start of some activity we want to explore in depth, for example, a certain DLL is attached to the process, a coupled process is started or a function is called. The start of a trace and the end of it are trivial significant events and are used in deciding whether the trace is circular, in determining the trace recording interval or its average statement current.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Computer memory analysis is based on interconnected structures of symbols and we state that there exists a memory language that extends a hierarchy of modeling and implementation languages (both domain-specific and general-purpose):

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Memory interpretation of the last words of Socrates:

“Crito, I own a” handle “to Æsculapius. Will you remember to” close it?

Socrates

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

This is a revised, edited, cross-referenced and thematically organized volume of selected DumpAnalysis.org blog posts about crash dump analysis and debugging written in July 2009 - January 2010 for software engineers developing and maintaining products on Windows platforms, quality assurance engineers testing software on Windows platforms and technical support and escalation engineers dealing with complex software issues. The fourth volume features:

- 13 new crash dump analysis patterns
- 13 new pattern interaction case studies
- 10 new trace analysis patterns
- 6 new Debugware patterns and case study
- Workaround patterns
- Updated checklist
- Fully cross-referenced with Volume 1, Volume 2 and Volume 3
- New appendixes

Product information:

• Title: Memory Dump Analysis Anthology, Volume 4
• Author: Dmitry Vostokov
• Language: English
• Product Dimensions: 22.86 x 15.24

• Paperback: 410 pages
• Publisher: Opentask (30 March 2010)
• ISBN-13: 978-1-906717-86-5

• Hardcover: 410 pages
• Publisher: Opentask (30 April 2010)
• ISBN-13: 978-1-906717-87-2

Back cover features memory space art image: Internal Process Combustion.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Demands and goals? 

That he [Sherlock Holmes] could play pieces, and difficult pieces, I knew well, because at my request he has played me some of Mendelssohn’s Lieder, and other favourites. When left to himself, however, he would seldom produce any music or attempt any recognized air.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 21

Typical memory dump analyst is sought after by different classes of corporate citizens:

I [Dr. Watson] found that he [Sherlock Holmes] had many acquaintances, and those in the most different classes of society.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 21

Layers of problem solvers (support levels 1, 2 and 3): 

When these fellows are at fault, they come to me [Sherlock Holmes], and I manage to put them on the right scent.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 23

One thousand and one memory dump:

There is a strong family resemblance about misdeeds, and if you have all the details of a thousand at your finger ends, it is odd if you can’t unravel the thousand and first.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 23

Memory analysis producers and consumers: 

I [Sherlock Holmes] listen to their story, they listen to my comments, […]

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 23

May be we should stop reasoning sometimes and just ask a memory dump. My favourite example is printer driver elimination for spooler crashes (uninstall one by one and test), where the reasoning technique can drive you mad. It is better to dump and look inside:

The train of reasoning ran, […]

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 23

Problem solving anti-patterns?

The question was how to identify an unknown prisoner. I could have done it in twenty-four hours. Lecoq took six months or so. It might be made a textbook for detectives to teach them what to avoid.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 24

Problem description specifies software version X. The customer insists. The dump points to version X-1. The customer retreats:

Here was an opportunity of taking the conceit out of him [Sherlock Holmes].

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 25

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Internal Process Combustion (to be featured on Memory Dump Analysis Anthology, Volume 4 backcover):

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Looks like yesterday the blog part of the portal experienced an almost threefold increase in the number of daily visits exceeding 2,400 visitors and, for the first time ever, bringing the total sliding number of unique monthly blog visits to more than 18,000:

Something happened on that day. The number of spam comments and trackbacks detected by Akismet plugin was the same as usual so spammers are ruled out.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Previously I wrote on how to get a 32-bit stack trace from a 32-bit process thread on an x64 system. There are situations when we are interested in all such stack traces, for example, from a complete memory dump. I wrote a script that extracts both 64-bit and WOW64 32-bit stack traces:

.load wow64exts
!for_each_thread "!thread @#Thread 1f;.thread /w @#Thread; .reload; kb 256; .effmach AMD64"

Example output fragment for a thread fffffa801f3a3bb0 from a very long debugger log file:

[...]

Setting context for owner process...
.process /p /r fffffa8013177c10
                                    

THREAD fffffa801f3a3bb0  Cid 4b4c.5fec  Teb: 000000007efaa000 Win32Thread: fffff900c1efad50 WAIT: (UserRequest) UserMode Non-Alertable
    fffffa8021ce4590  NotificationEvent
    fffffa801f3a3c68  NotificationTimer
Not impersonating
DeviceMap                 fffff8801b551720
Owning Process            fffffa8013177c10       Image:         application.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      14066428       Ticks: 301 (0:00:00:04.695)
Context Switch Count      248                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address mscorwks!Thread::intermediateThreadProc (0x00000000733853b3)
Stack Init fffffa60190e5db0 Current fffffa60190e5940
Base fffffa60190e6000 Limit fffffa60190df000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffffa60`190e5980 fffff800`01cba0fa nt!KiSwapContext+0x7f
fffffa60`190e5ac0 fffff800`01caedab nt!KiSwapThread+0x13a
fffffa60`190e5b30 fffff800`01f1d608 nt!KeWaitForSingleObject+0x2cb
fffffa60`190e5bc0 fffff800`01cb7973 nt!NtWaitForSingleObject+0x98
fffffa60`190e5c20 00000000`75183d09 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffffa60`190e5c20)
00000000`069ef118 00000000`75183b06 wow64cpu!CpupSyscallStub+0x9
00000000`069ef120 00000000`74f8ab46 wow64cpu!Thunk0ArgReloadState+0x1a
00000000`069ef190 00000000`74f8a14c wow64!RunCpuSimulation+0xa
00000000`069ef1c0 00000000`771605a8 wow64!Wow64LdrpInitialize+0x4b4
00000000`069ef720 00000000`771168de ntdll! ?? ::FNODOBFM::`string'+0x20aa1
00000000`069ef7d0 00000000`00000000 ntdll!LdrInitializeThunk+0xe

.process /p /r 0
Implicit thread is now fffffa80`1f3a3bb0
WARNING: WOW context retrieval requires
switching to the thread's process context.
Use .process /p fffffa80`1f6b2990 to switch back.
Implicit process is now fffffa80`13177c10
x86 context set
Loading Kernel Symbols
Loading User Symbols
Loading unloaded module list
Loading Wow64 Symbols
ChildEBP RetAddr
06aefc68 76921270 ntdll_772b0000!ZwWaitForSingleObject+0x15
06aefcd8 7328c639 kernel32!WaitForSingleObjectEx+0xbe
06aefd1c 7328c56f mscorwks!PEImage::LoadImage+0x1af
06aefd6c 7328c58e mscorwks!CLREvent::WaitEx+0x117
06aefd80 733770fb mscorwks!CLREvent::Wait+0x17
06aefe00 73377589 mscorwks!ThreadpoolMgr::SafeWait+0x73
06aefe64 733853f9 mscorwks!ThreadpoolMgr::WorkerThreadStart+0x11c
06aeff88 7699eccb mscorwks!Thread::intermediateThreadProc+0x49
06aeff94 7732d24d kernel32!BaseThreadInitThunk+0xe
06aeffd4 7732d45f ntdll_772b0000!__RtlUserThreadStart+0x23
06aeffec 00000000 ntdll_772b0000!_RtlUserThreadStart+0x1b
Effective machine: x64 (AMD64)

[...]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Comments in italics are mine and express my own views, thoughts and opinions

Windows Internals by M. Russinovich, D. Solomon and A. Ionescu:

CreateProcess and Increase Scheduling Priority privilege (p. 351)

MS-DOS apps share the same VDM (p. 353)

HKLM\S\CCS\C\WOW\DefaultSeparateVDM (p. 353)

IMAGE_FILE_UP_SYSTEM_ONLY PE characteristic to run on a single CPU (p. 358)

Upon creation initial thread starts in kernel mode in KiThreadStartup (p. 360)

His [Sherlock Holmes] hands were invariably blotted with ink and stained with chemicals, […]

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 19

Before I started memory dump analysis:

[…] how objectless was my [Dr. Watson] life, and how little there was to engage my attention.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 19

Most problem solvers are not polymaths:

His [Sherlock Holmes] ignorance was as remarkable as his knowledge. Of contemporary literature, philosophy and politics he appeared to know next to nothing.

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 19

Sherlock Holmes - his limits [numbered list]

A Study in Scarlet, Part 1, 2: The Science of Deduction, page 20

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Another common mistake I observe is relying on what debuggers report without double-checking. Present day debuggers, like WinDbg or GDB, are symbol-driven, they do not possess much of that semantic knowledge that a human debugger has. Also, it is better to report more than less: what is irrelevant can be skipped over by a skilled memory analyst but what looks suspicious to the problem at hand shall be double-checked to see if it is not coincidental. One example we consider here is Coincidental Symbolic Information. 

An application is frequently crashing. The process memory dump file shows only one thread left inside without any exception handling frames. In order to hypothesize about the probable cause the thread raw stack data is analyzed. It shows a few C++ STL calls with a custom smart pointer class and memory allocator like this:

app!std::vector<SmartPtr<ClassA>, std::allocator<SmartPtr<ClassA> > >::operator[]+

WinDbg !analyze-v command output points to this code:

FOLLOWUP_IP:
app!std::bad_alloc::~bad_alloc <PERF> (app+0x0)+0
00400000 4d  dec     ebp

Raw stack data contains a few symbolic references to bad_alloc destructor too:

[...]
0012f9c0  00000100
0012f9c4  00400100 app!std::bad_alloc::~bad_alloc <PERF> (app+0x100)
0012f9c8  00000000
0012f9cc  0012f9b4
0012f9d0  00484488 app!_NULL_IMPORT_DESCRIPTOR+0x1984
0012f9d4  0012fa8c
0012f9d8  7c828290 ntdll!_except_handler3
0012f9dc  0012fa3c
0012f9e0  7c82b04a ntdll!RtlImageNtHeaderEx+0xee
0012f9e4  00482f08 app!_NULL_IMPORT_DESCRIPTOR+0x404
0012f9e8  00151ed0
0012f9ec  00484c1e app!_NULL_IMPORT_DESCRIPTOR+0x211a
0012f9f0  00000100
0012f9f4  00400100 app!std::bad_alloc::~bad_alloc <PERF> (app+0x100)
[...]

By linking all these three pieces together an engineer hypothesized that the cause of failure is memory allocation. However, careful analysis reveals all of them as a coincidental symbolic information and renders hypothesis much less plausible:

1.  The address of app!std::bad_alloc::~bad_alloc is 00400000 which coincides with the start of the main application module:

0:000> lm a 00400000
start    end        module name
00400000 004c4000   app    (no symbols)

As a consequence, its assembly language code makes no sense:

0:000> u 00400000
app:
00400000 4d              dec     ebp
00400001 5a              pop     edx
00400002 90              nop
00400003 0003            add     byte ptr [ebx],al
00400005 0000            add     byte ptr [eax],al
00400007 000400          add     byte ptr [eax+eax],al
0040000a 0000            add     byte ptr [eax],al
0040000c ff              ???

2. All std::vector references are in fact fragments of a UNICODE string that can be dumped using du command:

[...]
0012ef14  00430056 app!std::vector<SmartPtr<ClassA>, std::allocator<SmartPtr<ClassA> > >::operator[]+0x16
0012ef18  00300038
0012ef1c  0043002e app!std::vector<SmartPtr<ClassA>, std::allocator<SmartPtr<ClassA> > >::size+0x1
[...]

0:000> du 0012ef14 l6
0012ef14  "VC80.C"

3. Raw stack data references to bad_alloc destructor are still module addresses in disguise, 00400100 or app+0×100, with nonsense assembly code:

0:000> u 00400100
app+0x100:
00400100 50              push    eax
00400101 45              inc     ebp
00400102 0000            add     byte ptr [eax],al
00400104 4c              dec     esp
00400105 010500571aac    add     dword ptr ds:[0AC1A5700h],eax
0040010b 4a              dec     edx
0040010c 0000            add     byte ptr [eax],al
0040010e 0000            add     byte ptr [eax],al

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -