Software Diagnostics Library

Finally the book came through the publishing process and is available on Amazon and other bookstores:

x64 Windows Debugging: Practical Foundations

- Dmitry Vostokov @ DumpAnalysis.org -

Today I celebrate 3 years of blogging that resulted in 1,430 posts across 8 blogs. I would like to thank everyone for their continuing support!

The updated timeline

This blog post belongs to the 4th year of blogging. 

- Dmitry Vostokov @ DumpAnalysis.org -

Pre-ordered today on Amazon this forthcoming book:

Advanced .NET Debugging (Addison-Wesley Microsoft Technology Series)

I was able to find TOC on InformIt. Looking forward to reading it. .NET crash dump (mixed managed and unmanaged code) and software trace analysis is a sizable part of my day-to-day activities.

When ordering I recalled that I’m was also working on a .NET debugging and memory dump analysis book:

Unmanaged Code: Escaping the Matrix of .NET

but I had to postpone it due to other commitments. It is now planned for the next year after I accumulate more material and real-world case studies.

Taking the opportunity, I also created a category .NET Debugging where I put some old blog posts and patterns related to managed code.

- Dmitry Vostokov @ DumpAnalysis.org -

It was reported that one server was hanging during automated reboot. Stack trace collection shows a few suspended and frozen threads. They all belong to the same process, ServiceA:

PROCESS 8545eb18  SessionId: 0  Cid: 0fec    Peb: 7ffd4000  ParentCid: 0fdc
    DirBase: 3fbeb8e0  ObjectTable: e19dd1d0  HandleCount: 169.
    Image: ServiceA.exe

THREAD 859cc900  Cid 0fec.0ff0  Teb: 7ffdf000 Win32Thread: bc1738d0 WAIT: (Unknown) KernelMode Non-Alertable
SuspendCount 1
FreezeCount 1
       859cca90  Semaphore Limit 0×2

THREAD 858c6480  Cid 0fec.0ff4  Teb: 7ffde000 Win32Thread: bc178c40 WAIT: (Unknown) KernelMode Non-Alertable
SuspendCount 1
       f55747d8  SynchronizationEvent

THREAD 859f2338  Cid 0fec.0ff8  Teb: 7ffdd000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
SuspendCount 1
FreezeCount 1
       859f24c8  Semaphore Limit 0×2

THREAD 859be2b8  Cid 0fec.0ffc  Teb: 7ffdc000 Win32Thread: bc1915d8 WAIT: (Unknown) KernelMode Non-Alertable
SuspendCount 1
FreezeCount 1
       859be448  Semaphore Limit 0×2

[...]

When zooming into this process we see that one thread was processing an exception:

0: kd> .process /r /p 8545eb18
Implicit process is now 8545eb18
Loading User Symbols

0: kd> !process 8545eb18
[...]
THREAD 858c6480  Cid 0fec.0ff4  Teb: 7ffde000 Win32Thread: bc178c40 WAIT: (Unknown) KernelMode Non-Alertable
SuspendCount 1
    f55747d8  SynchronizationEvent
Not impersonating
DeviceMap                 e10008e8
Owning Process            8545eb18       Image:         ServiceA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      6927           Ticks: 89866 (0:00:23:24.156)
Context Switch Count      156                 LargeStack
UserTime                  00:00:00.031
KernelTime                00:00:00.000
Win32 Start Address 0x611054cb
Start Address kernel32!BaseThreadStartThunk (0x7c8217ec)
Stack Init f5575000 Current f557471c Base f5575000 Limit f5571000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
f5574734 80833ec5 nt!KiSwapContext+0x26
f5574760 80829c14 nt!KiSwapThread+0x2e5
f55747a8 809a25c8 nt!KeWaitForSingleObject+0x346
f5574888 809a3739 nt!DbgkpQueueMessage+0x178
f55748ac 809a386e nt!DbgkpSendApiMessage+0x45
f5574938 8082d7ec nt!DbgkForwardException+0x90
f5574cf4 8088bed2 nt!KiDispatchException+0×1ea
f5574d5c 8088be86 nt!CommonDispatchException+0×4a
f5574da0 7c829c3a nt!Kei386EoiHelper+0×186
f5574dd0 00000000 kernel32!LoadResource+0×5d

We zoom into its parameters in search of semantically consistent output of .exr, .cxr and .trap commands:

0: kd> .thread 858c6480
Implicit thread is now 858c6480

0: kd> kv 100
ChildEBP RetAddr  Args to Child             
f5574734 80833ec5 858c6480 858c6528 00000200 nt!KiSwapContext+0x26
f5574760 80829c14 00000000 858c6480 f55747d0 nt!KiSwapThread+0x2e5
f55747a8 809a25c8 f55747d8 00000000 00000000 nt!KeWaitForSingleObject+0x346
f5574888 809a3739 8545eb18 00000000 f55748c0 nt!DbgkpQueueMessage+0x178
f55748ac 809a386e f55748c0 00000001 f5574d64 nt!DbgkpSendApiMessage+0x45
f5574938 8082d7ec f5574d10 00000001 00000000 nt!DbgkForwardException+0x90
f5574cf4 8088bed2 f5574d10 00000000 f5574d64nt!KiDispatchException+0×1ea
f5574d5c 8088be86 005bf4b4 61213267 badb0d00 nt!CommonDispatchException+0×4a
f5574da0 7c829c3a 71c22898 00000001 ffffffff nt!Kei386EoiHelper+0×186
f5574dd0 00000000 005bf448 00000023 00000000 kernel32!LoadResource+0×5d

After probing parameters for KiDispatchException we get these results pointing to ModuleA:

0: kd> .exr f5574d10
ExceptionAddress: 61213267 (ModuleA!GetData+0×0000b57f)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 00000000
   Parameter[1]: 71c22898
Attempt to read from address 71c22898

0: kd> .trap f5574d64
ErrCode = 00000004
eax=71c22898 ebx=0073a7a8 ecx=7c829c3a edx=71c1c000 esi=00000104 edi=00000000
eip=61213267 esp=005bf448 ebp=005bf4b4 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000202
ModuleA!GetData+0×0000b57f:
001b:61213267 0fb700 movzx   eax,word ptr [eax]  ds:0023:71c22898=????

We check its data using lmv WinDbg command and find out that it is old and needs to be updated. But we don’t stop our investigation here. The fact that ServiceA was suspended means that it was probably being debugged or memory dumped. And indeed, we see NTSD in a process list:

0: kd> !process 0 0
**** NT ACTIVE PROCESS DUMP ****
PROCESS 8619d5d0  SessionId: none  Cid: 0004    Peb: 00000000  ParentCid: 0000
    DirBase: 3fbeb020  ObjectTable: e1001e08  HandleCount: 1651.
    Image: System

PROCESS 85e95d88  SessionId: none  Cid: 019c    Peb: 7ffdf000  ParentCid: 0004
    DirBase: 3fbeb040  ObjectTable: e16d5f18  HandleCount:  19.
    Image: smss.exe

PROCESS 85e4fd88  SessionId: 0  Cid: 01cc    Peb: 7ffd4000  ParentCid: 019c
    DirBase: 3fbeb060  ObjectTable: e1561d70  HandleCount: 907.
    Image: csrss.exe

PROCESS 85e42d88  SessionId: 0  Cid: 01e4    Peb: 7ffde000  ParentCid: 019c
    DirBase: 3fbeb080  ObjectTable: e16a97b0  HandleCount: 504.
    Image: winlogon.exe

[...]

PROCESS 85a4dd18  SessionId: 0  Cid: 0fdc    Peb: 7ffda000  ParentCid: 0214
    DirBase: 3fbeb520  ObjectTable: e1aa5b38  HandleCount: 121.
    Image: ntsd.exe

[...]

If we zoom into NTSD process we would see that its main thread was waiting for a console input:

0: kd> !process 0fdc ff
[...]
THREAD 859f8768  Cid 0fdc.0fe0  Teb: 7ffdf000 Win32Thread: bc14cb38 WAIT: (Unknown) UserMode Non-Alertable
    859f8954  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 00001f98:
Current LPC port e19f03a0
Not impersonating
DeviceMap                 e10008e8
Owning Process            85a4dd18       Image:         ntsd.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      6932           Ticks: 89861 (0:00:23:24.078)
Context Switch Count      450                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.078
Win32 Start Address ntsd!mainCRTStartup (0×0100845a)
Start Address kernel32!BaseProcessStartThunk (0×7c8217f8)
Stack Init f55c5000 Current f55c4c08 Base f55c5000 Limit f55c1000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr 
f55c4c20 80833ec5 nt!KiSwapContext+0×26
f55c4c4c 80829c14 nt!KiSwapThread+0×2e5
f55c4c94 80920fba nt!KeWaitForSingleObject+0×346
f55c4d50 8088b3fc nt!NtRequestWaitReplyPort+0×776
f55c4d50 7c94860c nt!KiFastCallEntry+0xfc
0006ece0 7c947899 ntdll!KiFastSystemCallRet
0006ece4 7c94ec4a ntdll!ZwRequestWaitReplyPort+0xc
0006ed04 7c80cf8c ntdll!CsrClientCallServer+0×8c
0006edfc 7c872904 kernel32!ReadConsoleInternal+0×1b8
0006ee84 7c8018f4 kernel32!ReadConsoleA+0×3b
0006eedc 01005141 kernel32!ReadFile+0×64
0006ef04 01006974 ntsd!ConIn+0×183
0006ff38 010082d1 ntsd!MainLoop+0×1eb
0006ff44 01008589 ntsd!main+0×149
0006ffc0 7c82f23b ntsd!mainCRTStartup+0×12f
0006fff0 00000000 kernel32!BaseProcessStart+0×23

We follow LPC chain to csrss.exe to find out another blocked thread there:

0: kd> !lpc message 00001f98
Searching message 1f98 in threads …
Client thread 859f8768 waiting a reply from 1f98                         
Searching thread 859f8768 in port rundown queues …

Server communication port 0xe19b6b08
    Handles: 1   References: 1
    The LpcDataInfoChainHead queue is empty
        Connected port: 0xe19f03a0      Server connection port: 0xe1361d20

Client communication port 0xe19f03a0
    Handles: 1   References: 4
    The LpcDataInfoChainHead queue is empty

Server connection port e1361d20  Name: ServiceAPort
    Handles: 1   References: 233
    Server process  : 85e4fd88 (csrss.exe)
    Queue semaphore : 85e9b078
    Semaphore state 0 (0×0)
    The message queue is empty
    The LpcDataInfoChainHead queue is empty
Done.

0: kd> !process 85e4fd88 ff
[…]
THREAD 8549db60  Cid 01cc.1390  Teb: 7ffad000 Win32Thread: bc15aea8 WAIT: (Unknown) UserMode Non-Alertable
    8549dd4c  Semaphore Limit 0×1
Waiting for reply to LPC MessageId 00004feb:
Pending LPC Reply Message:
e191b6d0: [e1a162e8,e19ffc18]
Not impersonating
DeviceMap                 e10008e8
Owning Process            85e4fd88       Image:         csrss.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      12095          Ticks: 84698 (0:00:22:03.406)
Context Switch Count      35                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Start Address 0×75943b55
Stack Init f5625000 Current f5624bf0 Base f5625000 Limit f5622000 Call 0
Priority 15 BasePriority 13 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr 
f5624c08 80833ec5 nt!KiSwapContext+0×26
f5624c34 80829c14 nt!KiSwapThread+0×2e5
f5624c7c 809222f6 nt!KeWaitForSingleObject+0×346
f5624d38 8088b3fc nt!NtSecureConnectPort+0×6ce
f5624d38 7c94860c nt!KiFastCallEntry+0xfc
015ff778 7c947939 ntdll!KiFastSystemCallRet
015ff77c 77c2e7c3 ntdll!NtSecureConnectPort+0xc
015ff8a0 77c4607b RPCRT4!LRPC_CASSOCIATION::OpenLpcPort+0×21e
015ff8e0 77c45ffb RPCRT4!LRPC_CASSOCIATION::ActuallyDoBinding+0×55
015ff958 77c4f6a5 RPCRT4!LRPC_CASSOCIATION::AllocateCCall+0×190
015ff98c 77c4f5d1 RPCRT4!LRPC_BINDING_HANDLE::AllocateCCall+0×1f2
015ff9b8 77c4f201 RPCRT4!LRPC_BINDING_HANDLE::NegotiateTransferSyntax+0xd3
015ff9d0 77c4ed14 RPCRT4!I_RpcGetBufferWithObject+0×5b
015ff9e0 77c4f464 RPCRT4!I_RpcGetBuffer+0xf
015ff9f0 77cb30e4 RPCRT4!NdrGetBuffer+0×2e
015ffddc 779b4695 RPCRT4!NdrClientCall2+0×197
[…]

We follow LPC chain again to see that csrss.exe thread was waiting for a reply from our suspended and frozen ServiceA: 

0: kd> !lpc message 00004feb
Searching message 4feb in threads …
Client thread 8549db60 waiting a reply from 4feb                         
Searching thread 8549db60 in port rundown queues …

Server connection port e19a50e0  Name: ServiceAPort
    Handles: 1   References: 20
    Server process  : 8545eb18 (ServiceA.exe)
    Queue semaphore : 85443320
    Semaphore state 9 (0×9)
        Messages in queue:
        0000 e1a866e0 - Busy  Id=000022e7  From: 01e4.01e8  Context=80060004  [e19a50f0 . e1878688]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e1878688 - Busy  Id=00003297  From: 0ac0.0b54  Context=804d0045  [e1a866e0 . e1036740]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e1036740 - Busy  Id=00003986  From: 0ce4.0ce8  Context=00000042  [e1878688 . e1441228]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e1441228 - Busy  Id=00003a32  From: 0db4.0e14  Context=00000050  [e1036740 . e1a162e8]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e1a162e8 - Busy  Id=00004c75  From: 059c.05ac  Context=00000051  [e1441228 . e191b6d0]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e191b6d0 - Busy  Id=00004feb  From: 01cc.1390  Context=00000051  [e1a162e8 . e19ffc18]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e19ffc18 - Busy  Id=000055e3  From: 13fc.05b4  Context=800d0009  [e191b6d0 . e19f4ea0]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
        0000 e19f4ea0 - Busy  Id=00006844  From: 0b00.0f20  Context=006b3d60  [e19ffc18 . e19a50f0]
                   Length=011800e8  Type=0000000a (LPC_CONNECTION_REQUEST)
                   Data: 00000000 00000000 00000000 00000000 00000000 00000000
    The message queue contains 8 messages
    The LpcDataInfoChainHead queue is empty
Done.

It doesn’t look as a deadlock because, although we have a cyclic process wait chain ServiceA -> NTSD -> CSRSS -> ServiceA, NTSD was waiting for a different thread in CSRSS than the one in CSRSS waiting for a reply from ServiceA. If these threads are unrelated then we don’t have a deadlock, strictly speaking, because the latter involves activity chains with ownership, not a container dependency (a process is a container for threads). I illustrated all this on the following diagram:

- Dmitry Vostokov @ DumpAnalysis.org -

I’m very delighted to be a Dr. DebugLove! There are many Dr. Debug out there (Google shows 1,840,000 hits) but do they really love debugging like I do? Of course, they do, but I’m the first to acknowledge my strange love publicly by accepting a pseudonym.

- Dmitry Vostokov @ DumpAnalysis.org -

Last week I was comparing the existing collection of memory dump analysis patterns to the collection of trace analysis patterns (in formation) in the search of isomorphism (or more correctly, general morphism) similar to Missing Component pattern. It is not a coincidence that such pattern pairs can be formed. For example, it is possible to discern deadlocks from both crash dumps and software traces (if appropriate information is available there). Fundamentally, it is implied by the definition of a software trace as some sort of a memory dump. And we can see traces in memory dumps too, for example, Execution Residue pattern. Because raw stack data resides in stack pages and in contemporary operating systems they are created from zero pages (metaphorically, out of the void) we can say that stack regions of threads are sorted by their creation time, for example, in this process user memory dump:

0:017> !runaway 4
 Elapsed Time
  Thread       Time
   0:49c       0 days 5:16:31.076
   4:4d8       0 days 5:16:30.967
   3:4d0       0 days 5:16:30.967
   2:4cc       0 days 5:16:30.967
   1:4c8       0 days 5:16:30.967
   5:4e8       0 days 5:16:30.936
   6:b6c       0 days 5:16:15.695
   7:b70       0 days 5:16:15.679
   9:b88       0 days 5:16:15.586
   8:b84       0 days 5:16:15.586
  11:348       0 days 5:16:12.934
  10:bfc       0 days 5:16:12.934
  12:1200      0 days 5:15:16.528
  15:1298      0 days 5:15:15.220
  14:1290      0 days 5:15:15.220
  13:128c      0 days 5:15:15.220
  17:12e4      0 days 5:15:13.257
  16:12dc      0 days 5:15:13.257
  18:12ec      0 days 5:15:13.117
  20:12f4      0 days 5:15:13.085
  19:12f0      0 days 5:15:13.085
  21:17a0      0 days 5:13:16.321
  22:1628      0 days 5:13:15.729
  24:1778      0 days 1:35:50.773
  23:17ec      0 days 1:35:50.773
  25:1570      0 days 1:27:54.190
  26:1724      0 days 1:27:10.151
  27:1490      0 days 0:05:46.732
  28:1950      0 days 0:02:28.153
  29:19b4      0 days 0:00:58.108
  30:177c      0 days 0:00:38.358
  31:1798      0 days 0:00:23.351
  32:1a7c      0 days 0:00:08.343

If we have complete memory dumps we can also account for other processes and their elapsed time. Within stack pages we have partial stack traces but do not have exact timing information between them except for stack frames from the current frozen thread stack trace or, if we are lucky, from a partial stack trace from the past execution. However, the timing between frames from different stacks is undefined and we can only guess it from higher level considerations like semantics of procedure calls and other information.

These considerations and the notion of a poset (partially ordered set) let me thinking about memory dumps as posets. I even created my interpretation of POSET abbreviation for this occasion:

POSET 

Partially Ordered Software Execution Trace   

- Dmitry Vostokov @ DumpAnalysis.org -

Errata for the previous book Windows Debugging: Practical Foundations has been published:

Errata

Next week the updated version (revision 2.0) should be available on Amazon and other stores for both paperback and hardback titles. Digital version on Lulu has already been updated.

- Dmitry Vostokov @ DumpAnalysis.org -

The digital version of the book is finally available:

x64 Windows Debugging: Practical Foundations

Paperback should be available in 1-2 weeks on Amazon and other stores. When working on the book I fixed errors in the previous x86 version. Errata file for it should be available tomorrow.

- Dmitry Vostokov @ DumpAnalysis.org -

The new contemporary movement of engineers resisting dump analysis automation (including automated debugging and perhaps automated software construction too)

Inspired by Luddite movement.

- Dmitry Vostokov @ DumpAnalysis.org -

While I was listening to Klaus Schulze In Blue album a colleague sent me the link to a tool that reconstructs blue screens from minidumps (small memory dumps):

BlueScreenView (written by Nir Sofer)

I immediately downloaded it at it works even with kernel dumps but without pointing to a module that triggered the bugcheck (it shows modules for minidumps):

It ignores memory dumps and minidumps from x64 Windows so the next version I hope should do it

PS. Long time ago I was thinking about writing a kernel driver that saves BSOD screen and embeds it in a memory dump.

- Dmitry Vostokov @ DumpAnalysis.org -

The hierarchy of Ψ₁, …, Ψ₈, …, Ψ₁₆, …, Ψ₃₂, …, Ψ₆₄, …, …, …, Ψ_Ψ numbers where the subscript denotes the number of bits a memory address can have, so Ψ₃₂ and Ψ₆₄ are memorillion and quadrimemorillion of memory dumps respectively. We only need to figure out the meaning of Ψ₀ and Ψ_Ψ. Perhaps there is some meaning in Dirac notation here: <Ψ₀|Ψ_Ψ>. More on this later because I have to finish this week the book x64 Windows Debugging: Practical Foundations and write an errata file for the previous x86 version of the book series.

Note: Ψ is an M upside down.

- Dmitry Vostokov @ DumpAnalysis.org -

Jobs section on the portal features the new open position:

Dump Analyst for Samsung SDS India

- Dmitry Vostokov @ DumpAnalysis.org -

To be is to crash and to be crashed.

Dmitry Vostokov

- Dmitry Vostokov @ DumpAnalysis.org -

OpenTask plans to expand its Practical Foundations series and publish the following 2 books for the forthcoming Memory Dump Analysis Fundamentals certification (Unix track) being developed by Memory Analysis and Debugging Institute:

- Dmitry Vostokov @ DumpAnalysis.org -

Here is the front cover for the forthcoming book X64 Windows Debugging: Practical Foundations (ISBN: 978-1906717568):

- Dmitry Vostokov @ DumpAnalysis.org -

Here is another addition to identification of memory dumps coming from VMWare, VirtualPC and Xen Server virtualized Windows systems. Now I had a look at Windows Server 2008 Hyper-V host system running Windows Server 2008 as a guest and found that this information could serve as an identification if infrastructure components were installed:

kd> lm
[...]
fffffa60`00cc2000 fffffa60`00cd7000   winhv       (deferred)            
fffff960`00810000 fffff960`0081b000   VMBusVideoD (deferred)            
fffffa60`00c7e000 fffffa60`00cc2000   vmbus       (deferred)            
fffffa60`00df6000 fffffa60`00dfbb00   VMBusHID    (deferred)            
fffffa60`0201c000 fffffa60`02028000   VMBusVideoM (deferred)
[...]

winhv driver has lots of exported hypervisor related functions:

kd> x winhv!*
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for winhv.sys -
fffffa60`00cc3100 winhv!WinHvGetCurrentVpIndex (<no parameter info>)
fffffa60`00cc3160 winhv!WinHvSetSintOnCurrentProcessor (<no parameter info>)
fffffa60`00cc3230 winhv!WinHvNtProcessorToVpIndex (<no parameter info>)
fffffa60`00cc3260 winhv!WinHvDisconnectPort (<no parameter info>)
fffffa60`00cc32e0 winhv!WinHvDeletePort (<no parameter info>)
fffffa60`00cc35c0 winhv!WinHvMapGpaPages (<no parameter info>)
fffffa60`00cc36e0 winhv!WinHvSetVpRegisters (<no parameter info>)
fffffa60`00cc3e20 winhv!WinHvGetVpRegisters (<no parameter info>)
fffffa60`00cc3ed0 winhv!WinHvLowMemoryPolicyAutoDeposit (<no parameter info>)
fffffa60`00cc4110 winhv!WinHvSetPartitionProperty (<no parameter info>)
fffffa60`00cc4250 winhv!WinHvGetPartitionProperty (<no parameter info>)
fffffa60`00cc4290 winhv!WinHvPostMessage (<no parameter info>)
fffffa60`00cc4320 winhv!WinHvCreatePort (<no parameter info>)
fffffa60`00cc4380 winhv!WinHvConnectPort (<no parameter info>)
fffffa60`00cc43e0 winhv!WinHvCreateVp (<no parameter info>)
fffffa60`00cc4430 winhv!WinHvMapEventLogBuffer (<no parameter info>)
fffffa60`00cc44d0 winhv!WinHvCreateEventLogBuffer (<no parameter info>)
fffffa60`00cc4580 winhv!WinHvGetPartitionId (<no parameter info>)
fffffa60`00cc45d0 winhv!WinHvWithdrawAllMemory (<no parameter info>)
fffffa60`00cc4600 winhv!WinHvReleaseEventLogBuffer (<no parameter info>)
fffffa60`00cc4630 winhv!WinHvCreatePartition (<no parameter info>)
fffffa60`00cc49d0 winhv!WinHvDeletePartition (<no parameter info>)
fffffa60`00cc4f50 winhv!WinHvUnmapGpaPages (<no parameter info>)
fffffa60`00cc5150 winhv!WinHvInstallIntercept (<no parameter info>)
fffffa60`00cc5240 winhv!WinHvInitializeEventLogBufferGroup (<no parameter info>)
fffffa60`00cc52c0 winhv!WinHvDeleteVp (<no parameter info>)
fffffa60`00cc5340 winhv!WinHvGetPortProperty (<no parameter info>)
fffffa60`00cc53a0 winhv!WinHvSetEventLogGroupSources (<no parameter info>)
fffffa60`00cc55a0 winhv!WinHvOnInterrupt (<no parameter info>)
fffffa60`00cc5870 winhv!WinHvCancelTimer (<no parameter info>)
fffffa60`00cc5a20 winhv!WinHvSetAbsoluteTimer (<no parameter info>)
fffffa60`00cc5b40 winhv!WinHvSetEventLogCompletedNotificationRoutine (<no parameter info>)
fffffa60`00cc5b50 winhv!WinHvQueryInterceptIrql (<no parameter info>)
fffffa60`00cc5b60 winhv!WinHvGetSintMessage (<no parameter info>)
fffffa60`00cc5b90 winhv!WinHvAllocatePartitionSintIndex (<no parameter info>)
fffffa60`00cc5d60 winhv!WinHvClearVirtualInterrupt (<no parameter info>)
fffffa60`00cc5db0 winhv!WinHvFlushEventLogBuffer (<no parameter info>)
fffffa60`00cc5e10 winhv!WinHvQueryReferenceCounter (<no parameter info>)
fffffa60`00cc5e50 winhv!WinHvSignalEvent (<no parameter info>)
fffffa60`00cc5ea0 winhv!WinHvWriteGpa (<no parameter info>)
fffffa60`00cc5fb0 winhv!WinHvReadGpa (<no parameter info>)
fffffa60`00cc60c0 winhv!WinHvTranslateVirtualAddress (<no parameter info>)
fffffa60`00cc61a0 winhv!WinHvAssertVirtualInterrupt (<no parameter info>)
fffffa60`00cc6240 winhv!WinHvGetSintEventFlags (<no parameter info>)
fffffa60`00cc6e90 winhv!WinHvIsCompatibleServicedHypervisorImplementation (<no parameter info>)
fffffa60`00cc6e90 winhv!WinHvIsCompatibleServicedDriverImplementation (<no parameter info>)
fffffa60`00cc6e90 winhv!WinHvIsCompatibleHypervisorImplementation (<no parameter info>)
fffffa60`00cc6e90 winhv!WinHvIsCompatibleDriverImplementation (<no parameter info>)
fffffa60`00cc6ea0 winhv!WinHvLookupPortId (<no parameter info>)
fffffa60`00cc6ee0 winhv!WinHvLowMemoryPolicyRaiseException (<no parameter info>)
fffffa60`00cc6f90 winhv!WinHvLowMemoryPolicyReturnStatus (<no parameter info>)
fffffa60`00cc7070 winhv!WinHvQueryFeaturesState (<no parameter info>)
fffffa60`00cc71f0 winhv!WinHvDeleteEventLogBuffer (<no parameter info>)
fffffa60`00cc7220 winhv!WinHvUnmapEventLogBuffer (<no parameter info>)
fffffa60`00cc7250 winhv!WinHvFinalizeEventLogBufferGroup (<no parameter info>)
fffffa60`00cc7310 winhv!WinHvSetEndOfMessage (<no parameter info>)
fffffa60`00cc7340 winhv!WinHvAllocateSingleSintIndex (<no parameter info>)
fffffa60`00cc7530 winhv!WinHvClearLogicalProcessorRunTimeGroup (<no parameter info>)
fffffa60`00cc7560 winhv!WinHvSetLogicalProcessorRunTimeGroup (<no parameter info>)
fffffa60`00cc7740 winhv!WinHvGetMemoryBalance (<no parameter info>)
fffffa60`00cc77a0 winhv!WinHvGetLogicalProcessorRunTime (<no parameter info>)
fffffa60`00cc7830 winhv!WinHvGetNextChildPartition (<no parameter info>)
fffffa60`00ccf0e0 winhv!WinHvReportPresentHypervisor (<no parameter info>)
fffffa60`00ccf400 winhv!WinHvSetSint (<no parameter info>)
fffffa60`00ccf5b0 winhv!WinHvMapStatsPage (<no parameter info>)
fffffa60`00ccfa90 winhv!WinHvWithdrawMemory (<no parameter info>)
fffffa60`00ccfc80 winhv!WinHvDepositMemory (<no parameter info>)
fffffa60`00ccfd80 winhv!WinHvAllocatePortId (<no parameter info>)
fffffa60`00ccfff0 winhv!WinHvUnmapStatsPage (<no parameter info>)
fffffa60`00cd02d0 winhv!WinHvDeleteTimer (<no parameter info>)
fffffa60`00cd02f0 winhv!WinHvCreateTimer (<no parameter info>)
fffffa60`00cd0360 winhv!WinHvFreePortId (<no parameter info>)
fffffa60`00cd03c0 winhv!WinHvSupplyInterruptVector (<no parameter info>)
fffffa60`00cd0a80 winhv!WinHvAdjustFeaturesState (<no parameter info>)
fffffa60`00cd0aa0 winhv!WinHvQueryFeatureInformation (<no parameter info>)
fffffa60`00cd0ab0 winhv!WinHvGetIdentifierString (<no parameter info>)
fffffa60`00cd0bd0 winhv!WinHvFreeSingleSintIndex (<no parameter info>)
fffffa60`00cd0c20 winhv!WinHvFreePartitionSintIndex (<no parameter info>)
fffffa60`00cd0dd0 winhv!DllUnload (<no parameter info>)
fffffa60`00cd0f30 winhv!WinHvReclaimInterruptVector (<no parameter info>)
fffffa60`00cd1030 winhv!WinHvRestorePartitionState (<no parameter info>)
fffffa60`00cd1170 winhv!WinHvSavePartitionState (<no parameter info>)
fffffa60`00cd3050 winhv!DllInitialize (<no parameter info>)
fffffa60`00cd3990 winhv!DriverEntry (<no parameter info>)

If we have a clean virtualized guest without any tools installed then we can rely on hardware information:

kd> !sysinfo machineid
Machine ID Information [From Smbios 2.3, DMIVersion 35, Size=3752]
BiosVendor = American Megatrends Inc.
BiosVersion = 080002
BiosReleaseDate = 05/05/2008
SystemManufacturer = Microsoft Corporation
SystemProductName = Virtual Machine
SystemVersion = 5.0
BaseBoardManufacturer = Microsoft Corporation
BaseBoardProduct = Virtual Machine
BaseBoardVersion = 5.0

- Dmitry Vostokov @ DumpAnalysis.org -

We have the following crash pointing to Driver.sys 

7: kd> KL
Child-SP          RetAddr           Call Site
fffffadd`7671a678 fffff800`0102e5f4 nt!KeBugCheckEx
fffffadd`7671a680 fffff800`0102d587 nt!KiBugCheckDispatch+0x74
fffffadd`7671a800 fffffadd`88e5dbf3 nt!KiPageFault+0x207
fffffadd`7671a998 fffffadd`88df63f5 Driver!memcpy+0×83
fffffadd`7671a9a0 fffffadd`88dfe97b Driver!ItemCopyTo+0×85
fffffadd`7671a9e0 fffffadd`88e45bd1 Driver!CallbackEx+0×3cb
fffffadd`7671aa80 fffffadd`88dfb130 Driver!Callback+0×131
fffffadd`7671ab90 fffffadd`88dfaef3 Driver!Reply+0×1a0
fffffadd`7671ac40 fffffadd`88de9e23 Driver!OnDataReceive+0×1a3
fffffadd`7671acc0 fffff800`0124e932 Driver!ReaderThread+0×553
fffffadd`7671ad70 fffff800`010202b6 nt!PspSystemThreadStartup+0×3e
fffffadd`7671add0 00000000`00000000 nt!KxStartSystemThread+0×16

7: kd> !analyze -v
[...]
DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)
An attempt was made to access a pageable (or completely invalid) address at an interrupt request level (IRQL) that is too high.  This is usually caused by drivers using improper addresses. If kernel debugger is available get stack backtrace.
Arguments:
Arg1: 0000000000000007, memory referenced
Arg2: 0000000000000002, IRQL
Arg3: 0000000000000001, value 0 = read operation, 1 = write operation
Arg4: fffffadd88e5dbf3, address which referenced memory
[...]
TRAP_FRAME:  fffffadd7671a800 -- (.trap 0xfffffadd7671a800)
[...]

7: kd> .trap 0xfffffadd7671a800
[...]
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect

7: kd> r
Last set context:
rax=0000000000001000 rbx=0000000000000000 rcx=0000000000000007
rdx=fffffadda17d001d rsi=0000000000000000 rdi=0000000000000000
rip=fffffadd88e5dbf3 rsp=fffffadd7671a998 rbp=0000000000000001
 r8=0000000000000001  r9=fffffadda254f2f0 r10=0000000000000000
r11=0000000000000007 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz na pe nc
cs=0010 ss=0018 ds=0006 es=0000 fs=fadf gs=ffff efl=00010202
Driver!memcpy+0×83:
fffffadd`88e5dbf3 8801  mov byte ptr [rcx],al ds:0006:0007=??

.trap warning above perhaps explains why we have non-standard values in ds, fs and gs. Typical expected values in kernel mode are these (ds is ignored in 64-bit mode anyway):

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

7: kd> kL
Child-SP          RetAddr           Call Site
fffffadd`7671a998 fffffadd`88df63f5 Driver!memcpy+0×83
fffffadd`7671a9a0 fffffadd`88dfe97b Driver!ItemCopyTo+0×85
fffffadd`7671a9e0 fffffadd`88e45bd1 Driver!CallbackEx+0×3cb
fffffadd`7671aa80 fffffadd`88dfb130 Driver!Callback+0×131
fffffadd`7671ab90 fffffadd`88dfaef3 Driver!Reply+0×1a0
fffffadd`7671ac40 fffffadd`88de9e23 Driver!OnDataReceive+0×1a3
fffffadd`7671acc0 fffff800`0124e932 Driver!ReaderThread+0×553
fffffadd`7671ad70 fffff800`010202b6 nt!PspSystemThreadStartup+0×3e
fffffadd`7671add0 00000000`00000000 nt!KxStartSystemThread+0×16

We clearly have an instance of a NULL pointer data access. If we try to match this stack trace to known faults in database we would probably find many entries because memcpy is a generic function from C library. So we should try with ItemCopyTo. Indeed, we find a few matches but with slightly different stack traces:

b7535c7c b75931fa Driver!ItemCopyTo+0×6a
b7535ca4 b75c24c4 Driver!CallbackEx+0×23a
b7535d04 b7590c79 Driver!Callback+0xd4
b7535d44 b7590b41 Driver!Reply+0xe9
b7535d68 b7584b87 Driver!OnDataReceive+0×111
b7535dac 8094bea4 Driver!ReaderThread+0×397
b7535ddc 8088f61e nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

Offsets are different but the function names are the same. We also don’t see memcpy call but if we look at the faulted instruction we suspect it was inlined memcpy call:

eax=88642870 ebx=00000005 ecx=00000001 edx=00000005 esi=88f3f9a4 edi=00000029
eip=b758d3ca esp=b7535c6c ebp=b7535c7c iopl=0 nv up ei pl nz ac po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010212
Driver!ItemCopyTo+0×6a:
b758d3ca f3a5  rep movs dword ptr es:[edi],dword ptr [esi]

We also notice that the found stack trace is from x86 32-bit Windows but ours is from x64 Windows so we suspect the platformorphic fault here and check if we have a fix for x64 binaries.

- Dmitry Vostokov @ DumpAnalysis.org -

Paraphrasing “Knowing about knowing about knowing” (Side-box 0.1, Consciousness, David Rose) as “Knowing about knowing about problem solving”, I would suggest the following references to raise the level of awareness from meta-troubleshooting and meta-debugging, the subject of various general purpose debugging books to the next epistemic level. I’m currently reading the following books and let you know about my progress along the journey:

Toward a Unified Theory of Problem Solving: Views From the Content Domains

The Psychology of Problem Solving

The Cambridge Handbook of Expertise and Expert Performance

- Dmitry Vostokov @ DumpAnalysis.org -

Noticed today that it is still one of the top bestselling debugging books on Amazon:

- Dmitry Vostokov @ DumpAnalysis.org -

Finally the issue is available on Amazon and through other sellers:

Debugged! MZ/PE: Modeling Software Defects

I’m now planning the September issue and post details later. 

- Dmitry Vostokov @ DumpAnalysis.org -