Software Diagnostics Library

Setting a thread affinity mask to a specific processor or core makes that thread running in a single processor environment from that thread point of view. It is always scheduled to run on that processor. This potentially creates a problem found on real single processor environments if the processor runs another higher priority thread (Thread Starvation pattern) or loops at dispatch level IRQL (Dispatch Level Spin pattern). Therefore I call this pattern Affine Thread.

Here is one example. Dual core laptop was hanging and kernel memory dump showed the following Wait Chain pattern:

Resource @ nt!PopPolicyLock (0x80563080)    Exclusively owned
    Contention Count = 32
    NumberOfExclusiveWaiters = 9
     Threads: 8b3b08b8-01<*>
     Threads Waiting On Exclusive Access:
              872935f0       8744cb30       87535da8       8755a6b0      
              8588dba8       8a446c10       85891c50       87250020      
              8a6e7da8

The thread 8b3b08b8 blocked other 9 threads and had the following stack trace:

0: kd> !thread 8b3b08b8 1f
THREAD 8b3b08b8  Cid 0004.002c  Teb: 00000000 Win32Thread: 00000000 READY
Not impersonating
DeviceMap                 e1009248
Owning Process            8b3b2830       Image:         System
Wait Start TickCount      44419          Ticks: 8744 (0:00:02:16.625)
Context Switch Count      4579            
UserTime                  00:00:00.000
KernelTime                00:00:01.109
Start Address nt!ExpWorkerThread (0x8053867e)
Stack Init bad00000 Current bacffcb0 Base bad00000 Limit bacfd000 Call 0
Priority 15 BasePriority 12 PriorityDecrement 3 DecrementCount 16
ChildEBP RetAddr 
bacffcc8 804fd2c9 nt!KiUnlockDispatcherDatabase+0x9e
bacffcdc 8052a16f nt!KeSetSystemAffinityThread+0×5b
bacffd04 805caf03 nt!PopCompositeBatteryUpdateThrottleLimit+0×2d
bacffd24 805ca767 nt!PopCompositeBatteryDeviceHandler+0×1c5
bacffd3c 80529d3b nt!PopPolicyWorkerMain+0×25
bacffd7c 8053876d nt!PopPolicyWorkerThread+0xbf
bacffdac 805cff64 nt!ExpWorkerThread+0xef
bacffddc 805460de nt!PspSystemThreadStartup+0×34
00000000 00000000 nt!KiThreadStartup+0×16

Note this function and its first parameter: 

0: kd> !thread 8b3b08b8
[...]
bacffcdc 8052a16f 00000002 8a5b8cd8 00000030 nt!KeSetSystemAffinityThread+0×5b
[…]

The first parameter is KAFFINITY mask and 0×2 is 0y10 (binary) which is the second core. This thread had been already set to run on that core only:

0: kd> dt _KTHREAD 8b3b08b8
nt!_KTHREAD
   +0x000 Header           : _DISPATCHER_HEADER
[...]
   +0×124 Affinity         : 2
[…] 

Let’s look at our second core:

0: kd> ~1s

1: kd> kL 100
ChildEBP RetAddr 
a8f00618 acd21947 hal!KeAcquireInStackQueuedSpinLock+0x43
a8f00618 acd21947 tcpip!IndicateData+0x98
a8f00684 acd173e5 tcpip!IndicateData+0x98
a8f0070c acd14ef5 tcpip!TCPRcv+0xbb0
a8f0076c acd14b19 tcpip!DeliverToUser+0x18e
a8f007e8 acd14836 tcpip!DeliverToUserEx+0x95e
a8f008a0 acd13928 tcpip!IPRcvPacket+0x6cb
a8f008e0 acd13853 tcpip!ARPRcvIndicationNew+0x149
a8f0091c ba56be45 tcpip!ARPRcvPacket+0x68
a8f00970 b635801d NDIS!ethFilterDprIndicateReceivePacket+0x307
a8f00984 b63581b4 psched!PsFlushReceiveQueue+0x15
a8f009a8 b63585f9 psched!PsEnqueueReceivePacket+0xda
a8f009c0 ba56c8ed psched!ClReceiveComplete+0x13
a8f009d8 b7defdb5 NDIS!EthFilterDprIndicateReceiveComplete+0x7c
a8f00a08 b7df0f78 driverA+0x17db5
a8f00a64 ba55ec2c driverA+0x18f78
a8f00a88 b6b0962c NDIS!ndisMSendCompleteX+0x8d
a8f00a9c b6b0a36d driverB+0x62c
a8f00ab8 ba55e88f driverB+0x136d
a8f00ae0 b7de003c NDIS!NdisReturnPackets+0xe9
a8f00af0 ba55e88f driverA+0x803c
a8f00b18 b6358061 NDIS!NdisReturnPackets+0xe9
a8f00b30 ba55e88f psched!MpReturnPacket+0x3b
a8f00b58 acc877cc NDIS!NdisReturnPackets+0xe9
87749da0 00000000 afd!AfdReturnBuffer+0xe1

1: kd> r
eax=a8f005f8 ebx=a8f00624 ecx=8a9862ed edx=a8f00b94 esi=874e2ed0 edi=8a9862d0
eip=806e6a33 esp=a8f005ec ebp=a8f00618 iopl=0         nv up ei pl nz na po nc
cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00000202
hal!KeAcquireInStackQueuedSpinLock+0x43:
806e6a33 74ee            je      hal!KeAcquireInStackQueuedSpinLock+0x33 (806e6a23) [br=0]

1: kd> !running

System Processors 3 (affinity mask)
  Idle Processors 1

     Prcb      Current   Next   
  1  bab38120  8a0c8ae8  8b3a7318  …………….

We see the thread 8a0c8ae8 had been spinning on the second core for more than 2 minutes:

1: kd> !thread 8a0c8ae8 1f
THREAD 8a0c8ae8  Cid 0660.0124  Teb: 7ffd7000 Win32Thread: e338c498 RUNNING on processor 1
IRP List:
    8a960008: (0006,01b4) Flags: 00000900  Mdl: 87535908
Not impersonating
DeviceMap                 e2f155b8
Owning Process            87373020       Image:         APPLICATION.EXE
Wait Start TickCount      43918          Ticks: 9245 (0:00:02:24.453)
Context Switch Count      690                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:02:24.453
[…]

Its kernel time looks consistent with the starved thread waiting time:

0: kd> !thread 8b3b08b8 1f
THREAD 8b3b08b8  Cid 0004.002c  Teb: 00000000 Win32Thread: 00000000 READY
Not impersonating
DeviceMap                 e1009248
Owning Process            8b3b2830       Image:         System
Wait Start TickCount      44419          Ticks: 8744 (0:00:02:16.625)
[…]

For comparison, the spinning thread has affinity mask 0y11 (0×3) which means that it can be scheduled to run on both cores:

0: kd> dt _KTHREAD 8a0c8ae8
nt!_KTHREAD
   +0x000 Header           : _DISPATCHER_HEADER
[...]
   +0×124 Affinity         : 3
[…]

- Dmitry Vostokov @ DumpAnalysis.org -

In July-August Opentask publisher plans to have its own website. In the mean time here is the additional list of books to be published in the next 5-7 years starting from 2009 onwards:

- Memiotics (ISBN-13: 978-1906717087)

- Voice Recognition: Command and Control (ISBN-13: 978-1906717094)

- Memory Analysis: An Interdisciplinary Approach (ISBN-13: 978-1906717117)

- Deep Down C++ (ISBN-13: 978-1906717124)

- Management Bits: An Anthology from Reductionist Manager (ISBN-13: 978-1906717131)

- Classical, Quantum and Nonlinear Memoretics (ISBN-13: 978-1906717186)

- Crash Dump: A Software Engineering Autobiography (ISBN-13: 978-1906717193)

- Memoidealism: A New Kind of Philosophy (ISBN-13: 978-1906717209)

including 10-volume edition of Software Engineering Notebooks:

- Software Engineering Notebooks, Volume 1 (ISBN-13: 978-1906717148)

Details will be announced later on the publisher’s website.

Note: the book about voice recognition stands apart from the others. This is actually the title of the first book I wanted to write 5 years ago.

- Dmitry Vostokov @ DumpAnalysis.org -

Here is another 64-bit example of Hidden Exception pattern where looking at raw stack data helps in problem identification. Opening the dump in 6.8.0004.0 version of WinDbg shows this meaningless stack trace:

00000000`00000000 ??              ???

0:035> kL
Child-SP          RetAddr           : Call Site
00000000`00000000 00000000`00000000 : 0x0

Analysis command doesn’t help too:

FAULTING_IP:
ntdll!DbgBreakPoint+0
00000000`77ef2aa0 cc              int     3

EXCEPTION_RECORD:  ffffffffffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 0000000077ef2aa0 (ntdll!DbgBreakPoint)
   ExceptionCode: 80000003 (Break instruction exception)
  ExceptionFlags: 00000000
NumberParameters: 1
   Parameter[0]: 0000000000000000

FAULTING_THREAD:  0000000000000e50

DEFAULT_BUCKET_ID:  STATUS_BREAKPOINT

PROCESS_NAME:  application.exe

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION}  Breakpoint  A breakpoint has been reached.

NTGLOBALFLAG:  2000000

APPLICATION_VERIFIER_FLAGS:  0

LAST_CONTROL_TRANSFER:  from 0000000000000000 to 0000000000000000

STACK_TEXT: 
00000000`00000000 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x0

STACK_COMMAND:  kb

PRIMARY_PROBLEM_CLASS:  STATUS_BREAKPOINT

BUGCHECK_STR:  APPLICATION_FAULT_STATUS_BREAKPOINT_STACK_CORRUPTION

FOLLOWUP_IP:
ntdll!DbgBreakPoint+0
00000000`77ef2aa0 cc              int     3

SYMBOL_NAME:  ntdll!DbgBreakPoint+0

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: ntdll

IMAGE_NAME:  ntdll.dll

DEBUG_FLR_IMAGE_TIMESTAMP:  45d6cc72

FAILURE_BUCKET_ID:  ntdll.dll!DbgBreakPoint_80000003_STATUS_BREAKPOINT

BUCKET_ID:  X64_APPLICATION_FAULT_STATUS_BREAKPOINT_STACK_CORRUPTION_ntdll!DbgBreakPoint+0

Followup: MachineOwner
---------

However, looking at thread raw stack data allows us to get the problem stack trace showing that the full page heap enabled process detected heap corruption during free operation:

0:035> !teb
TEB at 000007fffff72000
    ExceptionList:        0000000000000000
    StackBase:            00000000080e0000
    StackLimit:           00000000080d8000
    SubSystemTib:         0000000000000000
    FiberData:            0000000000001e00
    ArbitraryUserPointer: 0000000000000000
    Self:                 000007fffff72000
    EnvironmentPointer:   0000000000000000
    ClientId:             0000000000000918 . 0000000000000e50
    RpcHandle:            0000000000000000
    Tls Storage:          0000000000000000
    PEB Address:          000007fffffd8000
    LastErrorValue:       0
    LastStatusValue:      c0000034
    Count Owned Locks:    0
    HardErrorMode:        0

0:035> dds 00000000080d8000 00000000080e0000
[...]
00000000`080dd7b8  00000000`77ef3202 ntdll!KiUserExceptionDispatcher+0×52
00000000`080dd7c0  00000000`0178070a
00000000`080dd7c8  00000000`080dd7c0 ; exception context
00000000`080dd7d0  00000000`08599d30
00000000`080dd7d8  00000000`00000020
00000000`080dd7e0  00000000`00000000
00000000`080dd7e8  00000000`00000000
00000000`080dd7f0  00001fa0`0010001f
00000000`080dd7f8  0053002b`002b0033
00000000`080dd800  00000202`002b002b
00000000`080dd808  00000000`00000000
[…]

0:035> .cxr 00000000`080dd7c0
rax=0000000000000001 rbx=0000000008599d30 rcx=000077fad8cd0000
rdx=00000000ffff0165 rsi=0000000077ec0000 rdi=0000000000000000
rip=0000000077ef2aa0 rsp=00000000080ddd58 rbp=0000000000000020
 r8=00000000ffffffff  r9=0000000000000000 r10=0000000000000007
r11=0000000000000000 r12=00000000080dde70 r13=0000000077f5d300
r14=0000000077f5d2f0 r15=0000000077f86bc0
iopl=0  nv up ei pl nz na pe nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll!DbgBreakPoint:
00000000`77ef2aa0 cc              int     3

0:035> kL 100
Child-SP          RetAddr           Call Site
00000000`080ddd58 00000000`77f5c78d ntdll!DbgBreakPoint
00000000`080ddd60 00000000`77f5da05 ntdll!RtlpDphReportCorruptedBlock+0×86d
00000000`080dde50 00000000`77f5a0f3 ntdll!RtlpDphNormalHeapFree+0×45
00000000`080ddfb0 00000000`77f60d5b ntdll!RtlpDebugPageHeapFree+0×203
00000000`080de0e0 00000000`77f3bcc8 ntdll!RtlDebugFreeHeap+0×3b
00000000`080de170 00000000`77edc095 ntdll!RtlFreeHeapSlowly+0×4e
00000000`080de2e0 000007ff`7fc2daab ntdll!RtlFreeHeap+0×15e
00000000`080de3f0 00000000`67fa288f msvcrt!free+0×1b
00000000`080de420 00000000`1000d3e9 dll!FreeMem+0xf
[…]
00000000`080df180 000007ff`7fe96cc9 RPCRT4!Invoke+0×65
00000000`080df1e0 000007ff`7fe9758d RPCRT4!NdrStubCall2+0×54d
00000000`080df7a0 000007ff`7fd697b4 RPCRT4!NdrServerCall2+0×1d
00000000`080df7d0 000007ff`7fde06b6 RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`080df800 000007ff`7fd6990d RPCRT4!DispatchToStubInCAvrf+0×16
00000000`080df830 000007ff`7fd69766 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×50d
00000000`080df9a0 000007ff`7fd6b214 RPCRT4!RPC_INTERFACE::DispatchToStub+0×2ec
00000000`080dfa20 000007ff`7fd6b9e3 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×63b
00000000`080dfae0 000007ff`7fd7007c RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×3bf
00000000`080dfba0 000007ff`7fd45369 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×710
00000000`080dfeb0 000007ff`7fd65996 RPCRT4!RecvLotsaCallsWrapper+0×9
00000000`080dfee0 000007ff`7fd65d51 RPCRT4!BaseCachedThreadRoutine+0xde
00000000`080dff50 00000000`77d6b6da RPCRT4!ThreadStartRoutine+0×21
00000000`080dff80 00000000`00000000 kernel32!BaseThreadStart+0×3a

Opening the dump in 6.9.3.113 version of WinDbg and running verbose analysis command shows “heuristic” stack trace (all symbols from raw stack) similar to old W2K extension stack command (see Guessing stack trace) where I highlighted exception processing hints in magenta:

0:035> !analyze -v
[...]
STACK_TEXT: 
00000000`77f15fb3 ntdll!RtlLookupFunctionTable
000007ff`5738e62c ole32!_pfnDliNotifyHook2 <PERF> (ole32+0x24e62c)
000007ff`57140000 ole32!_imp_TraceMessage <PERF> (ole32+0x0)
000007ff`57178356 ole32!ICoCreateInstanceEx
00000000`77ec0000 ntdll!_real <PERF> (ntdll+0x0)
00000000`77ef31dd ntdll!KiUserExceptionDispatcher
00000000`77f3ad68 ntdll!RtlAllocateHeapSlowly
00000000`77f967b8 ntdll!$$VProc_ImageExportDirectory
00000000`77f416ce ntdll!RtlpLookupFunctionEntryForStackWalks
00000000`77ef2aa0 ntdll!DbgBreakPoint
00000000`77ee5a36 ntdll!RtlVirtualUnwind
00000000`77f41c13 ntdll!RtlpWalkFrameChain
00000000`77f5d300 ntdll!`string'
00000000`77f5d2f0 ntdll!`string'
00000000`77f86bc0 ntdll!`string'
00000000`77ee455d ntdll!RtlpExecuteHandlerForException
00000000`77edc095 ntdll!RtlFreeHeap
00000000`77f979e4 ntdll!$$VProc_ImageExportDirectory
00000000`77ed609a ntdll!RtlCreateProcessParameters
00000000`77d5c71f kernel32!BasePushProcessParameters
00000000`77dc059b kernel32!UnhandledExceptionFilter
00000000`77ee6097 ntdll!RtlDispatchException
00000000`77f51285 ntdll!RtlpCaptureStackTraceForLogging
00000000`77f60270 ntdll!RtlDebugAllocateHeap
00000000`77f511a3 ntdll!RtlpExtendStackTraceDataBase
00000000`77d6ec00 kernel32!BasepComputeProcessPath
00000000`77d5c5b2 kernel32!BasePushProcessParameters
00000000`77d59c71 kernel32!CreateProcessInternalW
00000000`77dbc2df kernel32!BaseThreadStart
00000000`77ee6583 ntdll!_C_specific_handler
00000000`77f51432 ntdll!RtlpLogCapturedStackTrace
00000000`77f5e572 ntdll!RtlpDphLogStackTrace
00000000`77d5c4b2 kernel32!BasePushProcessParameters
00000000`77f4bb56 ntdll!DeleteNodeFromTree
00000000`77f4bf24 ntdll!RtlDeleteElementGenericTableAvl
00000000`77f574e1 ntdll!RtlpDphRemoveFromBusyList
00000000`77f5a0dd ntdll!RtlpDebugPageHeapFree
00000000`77f41799 ntdll!RtlCaptureStackBackTrace
00000000`67fa288f dll!FreeMem
00000000`77f5e559 ntdll!RtlpDphLogStackTrace
00000000`77f5a09f ntdll!RtlpDebugPageHeapFree
00000000`77f60d5b ntdll!RtlDebugFreeHeap
00000000`77f3bcc8 ntdll!RtlFreeHeapSlowly
00000000`77d4f7bc kernel32!CreateProcessInternalW
00000000`77f513bd ntdll!RtlpLogCapturedStackTrace
00000000`77ed495f ntdll!RtlDestroyProcessParameters
00000000`77d5c7c2 kernel32!BasePushProcessParameters
00000000`77dc0730 kernel32!`string’
00000000`77d813f0 kernel32!`string’
00000001`000000e0 application!_imp_RegQueryValueExW <PERF> (application+0xe0)
00000000`77ef9971 ntdll!RtlImageNtHeader
00000000`77d6b302 kernel32!BaseCreateStack
00000000`77d5c8a1 kernel32!BaseInitializeContext
00000000`77ef5a81 ntdll!CsrClientCallServer
00000000`77d5c829 kernel32!CreateProcessInternalW
00000001`00000001 application!_imp_RegQueryValueExW <PERF> (application+0×1)
00000001`00000000 application!_imp_RegQueryValueExW <PERF> (application+0×0)
000007ff`57178717 ole32!CProcessActivator::CCICallback
000007ff`571921bf ole32!CoCreateInstance
00000000`77d59620 kernel32!BaseProcessStart
00000000`77dc05d4 kernel32!UnhandledExceptionFilter
00000000`77e346e0 kernel32!__PchSym_ <PERF> (kernel32+0xf46e0)
00000000`77d6b6da kernel32!BaseThreadStart
000007ff`7fe7a934 RPCRT4!Ndr64pSizing
00000000`77f41c93 ntdll!RtlpWalkFrameChain
00000000`77edca76 ntdll!RtlAllocateHeap
00000000`77d40000 kernel32!_imp_memcpy <PERF> (kernel32+0×0)
00000000`77fa0100 ntdll!RtlpStaticDebugInfo
00000000`77ed08b3 ntdll!vsnwprintf
00000000`77dbf42c kernel32!StringCchPrintfW
00000000`77d6e314 kernel32!CloseHandle
00000000`77dc06d8 kernel32!UnhandledExceptionFilter
00000000`77e0a958 kernel32!`string’
00000000`77e29080 kernel32!CfgmgrDllString
000007ff`7fd697b4 RPCRT4!DispatchToStubInCNoAvrf
00000000`77efc2d9 ntdll!bsearch
00000000`77efc791 ntdll!RtlpFindUnicodeStringInSection
00000000`77e23454 kernel32!__PchSym_ <PERF> (kernel32+0xe3454)
00000000`77e1d324 kernel32!g_hModW03A2409
00000000`77e1d330 kernel32!g_hModW03A2409
00000000`77f39fce ntdll!RtlLookupFunctionEntry
00000000`77f39231 ntdll!RtlDispatchException
00000000`77fa3c70 ntdll!RtlpCallbackEntryList
00000000`77d92290 kernel32!_C_specific_handler
00000000`77e30033 kernel32!__PchSym_ <PERF> (kernel32+0xf0033)
000007ff`7fd65d51 RPCRT4!ThreadStartRoutine
00000000`77efc437 ntdll!RtlpLocateActivationContextSection
00000000`77ef8708 ntdll!RtlFindActivationContextSectionString
000007ff`7fc2dab0 msvcrt!free
00000000`77fc5f08 ntdll!CsrPortMemoryRemoteDelta <PERF> (ntdll+0×105f08)
00000000`77fc5fe0 ntdll!CsrPortMemoryRemoteDelta <PERF> (ntdll+0×105fe0)
00000000`77fc5dd0 ntdll!CsrPortMemoryRemoteDelta <PERF> (ntdll+0×105dd0)
00000000`77fc6250 ntdll!CsrPortMemoryRemoteDelta <PERF> (ntdll+0×106250)
00000000`77fc2614 ntdll!CsrPortMemoryRemoteDelta <PERF> (ntdll+0×102614)
00000000`77fb2e28 ntdll!CsrPortMemoryRemoteDelta <PERF> (ntdll+0xf2e28)
000007ff`7fc00000 msvcrt!_imp_MultiByteToWideChar <PERF> (msvcrt+0×0)
000007ff`7fc7fb78 msvcrt!bufin <PERF> (msvcrt+0×7fb78)
00000000`77ef3202 ntdll!KiUserExceptionDispatcher
00000000`77f86220 ntdll!`string’
00000000`77f5c78d ntdll!RtlpDphReportCorruptedBlock
00000000`77f5d1b0 ntdll!`string’
00000000`77f5d1e0 ntdll!`string’
00000000`77f5d200 ntdll!`string’
00000000`77f5da05 ntdll!RtlpDphNormalHeapFree
000007ff`7fde06b6 RPCRT4!DispatchToStubInCAvrf
000007ff`7fd7007c RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls
000007ff`7fd45369 RPCRT4!RecvLotsaCallsWrapper
000007ff`7fd65996 RPCRT4!BaseCachedThreadRoutine
00000000`77f57370 ntdll!RtlpDphFindBusyMemory
00000000`77f5a0f3 ntdll!RtlpDebugPageHeapFree
000007ff`57197e5b ole32!CRetailMalloc_Free
00000000`77c30000 USER32!InternalCreateDialog
000007ff`5719a21a ole32!COleStaticMutexSem::Request
00000000`77d6d6e1 kernel32!FreeLibrary
000007ff`7ebc0000 OLEAUT32!_imp_RegFlushKey <PERF> (OLEAUT32+0×0)
000007ff`56db3024 msxml3!ModelInit::~ModelInit
00000000`77d6e76c kernel32!LocalAlloc
000007ff`7fc2daab msvcrt!free
000007ff`7fd70000 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls
000007ff`7ff0b397 ADVAPI32!LocalBaseRegOpenKey
000007ff`7ff0b977 ADVAPI32!RegQueryValueExW
000007ff`7ff0b20e ADVAPI32!LocalBaseRegCloseKey
000007ff`7ff0b19f ADVAPI32!RegCloseKey
00000000`77ef7b33 ntdll!RtlNtStatusToDosError
000007ff`7fd66238 RPCRT4!LRPC_SCALL::ImpersonateClient
00000000`77efbcdf ntdll!RtlEqualSid
000007ff`7fd662a6 RPCRT4!LRPC_SCALL::RevertToSelf
000007ff`7ff0c6d4 ADVAPI32!GetTokenInformation
000007ff`7fd5cb7b RPCRT4!RpcRevertToSelf
000007ff`7fd666b2 RPCRT4!SCALL::AddToActiveContextHandles
000007ff`7fd37f76 RPCRT4!NDRSContextUnmarshall2
00000000`77f5a001 ntdll!RtlpDebugPageHeapFree
000007ff`7fd6f32b RPCRT4!DCE_BINDING::`scalar deleting destructor’
000007ff`7fd604c3 RPCRT4!RpcStringBindingParseW
000007ff`7fd30000 RPCRT4!_imp_GetSecurityDescriptorDacl <PERF> (RPCRT4+0×0)
000007ff`7fd66374 RPCRT4!NdrServerContextNewUnmarshall
000007ff`7fd605e5 RPCRT4!RpcStringFreeA
000007ff`7fd69e00 RPCRT4!NdrServerInitialize
000007ff`7fd65e81 RPCRT4!RPC_INTERFACE::CheckSecurityIfNecessary
000007ff`7fd6b9e3 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest
000007ff`7fd66c1e RPCRT4!NdrUnmarshallHandle
000007ff`7fd69a75 RPCRT4!Invoke
000007ff`7fe96cc9 RPCRT4!NdrStubCall2
00000000`77f5e500 ntdll!RtlpDphFreeDelayedBlocksFromHeap
000007ff`7fd608b4 RPCRT4!SVR_BINDING_HANDLE::SVR_BINDING_HANDLE
00000000`77ef7dbb ntdll!RtlInitializeCriticalSectionAndSpinCount
000007ff`7fd60100 RPCRT4!DCE_BINDING::StringBindingCompose
000007ff`7fe9758d RPCRT4!NdrServerCall2
000007ff`7fd5cffd RPCRT4!ParseAndCopyEndpointField
000007ff`7fd604ce RPCRT4!RpcStringBindingParseW
000007ff`7fd6990d RPCRT4!RPC_INTERFACE::DispatchToStubWorker
000007ff`7fc40b0f msvcrt!getptd
000007ff`7fd37eaf RPCRT4!RpcServerInqCallAttributesW
000007ff`7fd65e9c RPCRT4!RPC_INTERFACE::CheckSecurityIfNecessary
000007ff`7fd69766 RPCRT4!RPC_INTERFACE::DispatchToStub
000007ff`7fd6b214 RPCRT4!LRPC_SCALL::DealWithRequestMessage
000007ff`7fd70466 RPCRT4!LRPC_ADDRESS::DereferenceAssociation
000007ff`7fd6ee28 RPCRT4!LRPC_SASSOCIATION::DealWithCopyMessage
000007ff`7fd65d30 RPCRT4!ThreadStartRoutine
00000000`77d6b6a0 kernel32!BaseThreadStart

- Dmitry Vostokov @ DumpAnalysis.org -

The number of monthly site visits reached 15,000 (Google analytics reports more than 16,000). The upward trend continues since 10,000 Visit Mark at the end of January, 2008. I’m planning to add more attractive features to the portal during this summer. Stay tuned and participate more actively in SEO resonance (75% of all traffic comes from search engines)

- Dmitry Vostokov @ DumpAnalysis.org -

Although the first bug (the real one) was found in Mark II (see Software bug) the first general-purpose electronic computer was ENIAC and surely it had defects like overflow. In 80s there was an electronic music group called Software. I have a few CDs and listen to them sometimes. One album is called Software-Visions and it has these tracks (one of them is called Xenix - Microsoft UNIX-based OS):

1. Software Visions
2. Secrets
3. Stranger
4. Realtime
5. Mainframe
6. Snobol
7. Xenix
8. Syntax
9. Overflow
10. Interface
11. Eniac

- Dmitry Vostokov @ DumpAnalysis.org -

Nested exception analysis is much simpler in managed code than in unmanaged. Exception object references the inner exception if any and so on:

Exception.InnerException

WinDbg does a good job traversing all nested exceptions when executing !analyze -v command. In the following example of a Windows forms application crash ObjectDisposedException (shown in red) was re-thrown as Exception object with “Critical error” message (shown in magenta) which was re-thrown several times as Exception object with “Critical program error” message (shown in blue) that finally resulted in the process termination request in the top level exception handler:

MANAGED_STACK:
(TransitionMU)
001374B0 0B313757 System!System.Diagnostics.Process.Kill()+0x37
001374E4 0B3129C7 Component!Foo.HandleUnhandledException(System.Exception)+0x137
001374F4 07C0A7D3 Component!Foo+FooBarProcessMenuCommand(System.String)+0x33
(TransitionUM)
(TransitionMU)
[...]

EXCEPTION_OBJECT: !pe 3398614
Exception object: 03398614
Exception type: System.Exception
Message: Critical program error
InnerException: System.Exception, use !PrintException 03398560 to see more StackTrace (generated):
    SP       IP       Function
    001371A8 07C0CDD8 Foo.BarUserInteraction.Process(System.String)
    00137258 07C0CCA6 Foo.BarUserInteraction.ProcessUserInteraction(Sub, BarStepType)
    00137268 07C0A9BA Foo.BarMenu.Process(CMD)
    00137544 07C0A8D8 Foo.BarMenu.ProcessCMD(CMD)
    0013756C 07C0A7BE Foo+FooBar.ProcessBarMenuCommand(System.String)

StackTraceString: <none>
HResult: 80131500

EXCEPTION_OBJECT: !pe 3398560
Exception object: 03398560
Exception type: System.Exception
Message: Critical program error
InnerException: System.Exception, use !PrintException 033984ac to see more StackTrace (generated):
    SP       IP       Function
    00137154 07C0D4CA Foo.BarThreads+ProcessOpenQuery.Execute()
    00137218 07C0D3B3 Foo.BarMenu.ProcessQuery()
    00137220 07C0CCF3 Foo.BarUserInteraction.Process(System.String)

StackTraceString: <none>
HResult: 80131500

EXCEPTION_OBJECT: !pe 33984ac
Exception object: 033984ac
Exception type: System.Exception
Message: Critical program error
InnerException: System.Exception, use !PrintException 033983ec to see more StackTrace (generated):
    SP       IP       Function
    0013704C 0A6149DD Foo.Bar.OpenQueryThreaded(Foo.BarParameter)
    00137154 0A6140D0 Foo.BarThreads+ProcessParameter.Execute()
[…]

StackTraceString: <none>
HResult: 80131500

EXCEPTION_OBJECT: !pe 33983ec
Exception object: 033983ec
Exception type: System.Exception
Message: Critical program error
InnerException: System.Exception, use !PrintException 033982fc to see more StackTrace (generated):
    SP       IP       Function
    00137008 0ACA59F1 Foo.BarApplication.Refresh(Boolean, Boolean)
    001370C4 0A6144E0 Foo.Bar.OpenQueryThreaded(Foo.BarParameter)

StackTraceString: <none>
HResult: 80131500

EXCEPTION_OBJECT: !pe 33982fc
Exception object: 033982fc
Exception type: System.Exception
Message: Critical program error
InnerException: System.Exception, use !PrintException 03398260 to see more StackTrace (generated):
    SP       IP       Function
    00136F3C 0AE24983 Foo.BarDisplay.ShowVariableScreen(Foo.variables.BarVariables)
    00136FDC 0AE204F6 Foo.variables.BarVariables.ShowVariableScreen()
    00137070 0ACAFE1D Foo.BarApplication.ShowVariableScreen(Boolean)
    00137080 0ACA5977 Foo.BarApplication.Refresh(Boolean, Boolean)

StackTraceString: <none>
HResult: 80131500

EXCEPTION_OBJECT: !pe 3398260
Exception object: 03398260
Exception type: System.Exception
Message: Critical error
InnerException: System.ObjectDisposedException, use !PrintException 03397db8 to see more StackTrace (generated):
    SP       IP       Function
    00136FB4 0AE24905 Foo.BarDisplay.ShowVariableScreen(Foo.variables.BarVariables)

StackTraceString: <none>
HResult: 80131500

EXCEPTION_OBJECT: !pe 3397db8
Exception object: 03397db8
Exception type: System.ObjectDisposedException
Message: Cannot access a disposed object.
InnerException: <none>
StackTrace (generated):
    SP       IP       Function
    00136258 06D36158 System.Windows.Forms.Control.CreateHandle()
    001362B8 06D38F96 System.Windows.Forms.Control.get_Handle()
    001362C4 0B0C8C68 System.Windows.Forms.Control.PointToScreen(System.Drawing.Point)
    001362F0 0B0CECB4 System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)
    00136314 0B0C8BB7 System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)
    00136384 06D385A0 System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
    001363E8 0A69C73E System.Windows.Forms.ButtonBase.WndProc(System.Windows.Forms.Message ByRef)
    00136424 0A69C54D System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)
    0013642C 06D37FAD System.Windows.Forms.Control+ControlNativeWindow.OnMessage(System.Windows.Forms.Message ByRef)
    00136430 06D37F87 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)
    00136440 06D37D9F System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)

StackTraceString: <none>
HResult: 80131622

[…]

EXCEPTION_MESSAGE:  Cannot access a disposed object.

STACK_TEXT: 
00137448 7c827c1b ntdll!KiFastSystemCallRet
0013744c 77e4201b ntdll!NtTerminateProcess+0xc
0013745c 05d78202 kernel32!TerminateProcess+0x20
[...]

- Dmitry Vostokov @ DumpAnalysis.org -

I’m thinking big for a full-color book to celebrate the forthcoming anniversary of Memory Dump Analysis Anthology. Preliminary details:

• Title: Encyclopedia of Crash Dump Analysis Patterns
• Author: Dmitry Vostokov
• Publisher: Opentask (15 April 2009)
• Language: English
• Product Dimensions: 21.6 x 14.0
• ISBN-13: 978-1-906717-21-6
• Paperback: 400 pages

- Dmitry Vostokov @ DumpAnalysis.org -

There are currently 86 patterns in 67 groups and more are coming. I’m working the first two weeks in July to classify them. The classification scheme(s) should appear around 15th of July.

- Dmitry Vostokov @ DumpAnalysis.org -

In one of my previous posts I wrote that in the case of a first-chance exception it is not possible to see it in a process crash dump because the entire exception processing was done in the kernel space (see the post How to distinguish between 1st and 2nd chances):

However the picture changes if we have Nested Exceptions pattern. In this case we should expect traces of inner exception processing like exception dispatcher code or exception handlers to be present on a raw stack dump:

Consider the following C++ code with two exception handlers:

 __try
 {
   __try
   {
     *(int *)NULL = 0;  // Exception 1
                        // Dump1 1st chance
   }
   __except (EXCEPTION_EXECUTE_HANDLER)
   {
     std::cout << “Inner” << std::endl;
     *(int *)NULL = 0;  // Exception 2
                        // Dump2 1st chance
   }
 }
 __except (EXCEPTION_EXECUTE_HANDLER)
 {
   std::cout << “Outer” << std::endl;
   *(int *)NULL = 0;    // Exception 3
                        // Dump3 1st chance
                        // Dump4 2nd chance
 }

If we run the actual program and we have set a default postmortem debugger we get a second-chance exception dump (Dump4). The program first outputs “Inner” and then “Outer” on a console and then crashes. When we look at the dump we see second-chance exception processing code where the exception record for NtRaiseException is the same and points to Exception 3 context (shown in red color): 

This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(11dc.f94): Access violation - code c0000005 (first/second chance not available)
*** ERROR: Module load completed but symbols could not be loaded for NestedException.exe
NestedException+0x1a72:
00000001`40001a72 c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

0:000> !teb
TEB at 000007fffffde000
    ExceptionList:        0000000000000000
    StackBase:            0000000000130000
    StackLimit:           000000000012d000
    SubSystemTib:         0000000000000000
    FiberData:            0000000000001e00
    ArbitraryUserPointer: 0000000000000000
    Self:                 000007fffffde000
    EnvironmentPointer:   0000000000000000
    ClientId:             00000000000011dc . 0000000000000f94
    RpcHandle:            0000000000000000
    Tls Storage:          000007fffffde058
    PEB Address:          000007fffffd5000
    LastErrorValue:       0
    LastStatusValue:      c000000d
    Count Owned Locks:    0
    HardErrorMode:        0

0:000> dqs 000000000012d000 0000000000130000
[...]
00000000`0012f918  00000000`00000006
00000000`0012f920  00000000`00000000
00000000`0012f928  00000000`775a208d ntdll!KiUserExceptionDispatch+0×53
00000000`0012f930  00000000`00000000
00000000`0012f938  00000000`0012f930 ; exception context
00000000`0012f940  01c8d5f0`00000000
00000000`0012f948  00000000`00000000
[…]

0:000> ub ntdll!KiUserExceptionDispatch+0x53
ntdll!KiUserExceptionDispatch+0x35:
00000000`775a206f xor     edx,edx
00000000`775a2071 call    ntdll!RtlRestoreContext (00000000`775a2255)
00000000`775a2076 jmp     ntdll!KiUserExceptionDispatch+0x53 (00000000`775a208d)
00000000`775a2078 mov     rcx,rsp
00000000`775a207b add     rcx,4D0h
00000000`775a2082 mov     rdx,rsp
00000000`775a2085 xor     r8b,r8b
00000000`775a2088 call    ntdll!NtRaiseException (00000000`775a1550)

0:000> .cxr 00000000`0012f930
rax=00000001400223d0 rbx=0000000000000000 rcx=0000000140022128
rdx=0000000000000001 rsi=0000000000000006 rdi=0000000140022120
rip=0000000140001a72 rsp=000000000012fed0 rbp=0000000000000000
 r8=000007fffffde000  r9=0000000000000001 r10=0000000000000000
r11=0000000000000246 r12=0000000000000000 r13=0000000000000002
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl zr ac po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010256
NestedException+0x1a72:
00000001`40001a72 c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

However if we have first-chance exception Dump3 from some exception monitoring program we see that NtRaiseException parameter points to ”Inner” Exception 2 context (a different and earlier address, shown in magenta color):

This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(11dc.f94): Access violation - code c0000005 (first/second chance not available)
*** ERROR: Module load completed but symbols could not be loaded for NestedException.exe
NestedException+0x1a72:
00000001`40001a72 c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

0:000> dqs 000000000012d000 0000000000130000
[...]
00000000`0012f918  00000000`00000006
00000000`0012f920  00000000`00000000
00000000`0012f928  00000000`775a2068 ntdll!KiUserExceptionDispatch+0×2e
00000000`0012f930  00000000`00000000
00000000`0012f938  00000000`0012f930 ; exception context
00000000`0012f940  01c8d5f0`00000000
[…]

0:000>  .cxr 00000000`0012f930
rax=00000001400223d0 rbx=0000000000000000 rcx=0000000140022128
rdx=0000000000000001 rsi=0000000000000006 rdi=0000000140022120
rip=00000001400019fa rsp=000000000012fed0 rbp=0000000000000000
 r8=000007fffffde000  r9=0000000000000001 r10=0000000000000000
r11=0000000000000246 r12=0000000000000000 r13=0000000000000002
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl zr ac po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010256
NestedException+0x19fa:
00000001`400019fa c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

Similar can be said about Dump2 where NtRaiseException parameter points to Exception 1 context. But Dump1 doesn’t have any traces of exception processing as expected.

All 4 dump files can be downloaded from FTP to play with:

ftp://dumpanalysis.org/pub/CDAPatternNestedExceptions.zip 

- Dmitry Vostokov @ DumpAnalysis.org -

In 2007 in Retrospection (Part 2) post I put the most frequent search keywords what brought people to my site. Unfortunately due my mistake I lost all cumulative data for that period and began collecting it again since March, 2008. Here is the new list of top 100 keywords out of more than 22,000 for March - June (with my links where I try to provide answers or point to other resources):

kifastsystemcallret
crash dump analysis
crash dump
ntdll!kifastsystemcallret
vista crash dump
time travel debugging
dump analysis
crash dumps
windbg commands
memory dump analysis anthology
memory intelligence analysis
crashdump
your debugger is not using the correct symbols
symbol file could not be found
kmode_exception_not_handled
minidump analyze
windbg analyze
c++ dereferencing null debug
windows crash dump analysis
system_service_exception
kernel32!pnlsuserinfo
warning: frame ip not in any known module. following frames may be wrong.
win32 error 0n2
previously announced volume is available in trade
windbg script
kernel_mode_exception_not_handled
practical foundations of debugging
getcontextstate failed, 0×80070026
memory analysis intelligence
minidump analyzer
dxg.sys
crash dump vista
dr watson vista
calling+kernel+functions+from+userspace
crash dump analyzer
how to open corrupt memory dump
rtlfreeheap+38e
how to use windbg
dd srvcomputername
dmitry vostokov
warning: stack unwind information not available. following frames may be wrong.
drwtsn32 vista
nasdaq:aapl
1000 application fault crash dump
exfreepoolwithtag
time+travel+debugging
dumpanalysis.org
minidump analysis
your debugger is not using the correct symbols
windows via c/c++
windows internals
minidump
aapl
memoretics
user mode process dumper
memory dump analysis
type referenced: kernel32!pnlsuserinfo
ibmsprem.exe
memory dump
userdump
windbg !analyze
zwusergetmessage
memory dump analysis anthology, volume 1
pool corruption
windbg
windows vista crash dump
failure_bucket_id
frame ip not in any known module
kiswapcontext
werfault.exe
what is a crash dump
flow analysis was incomplete, some code may be missing
wanarpv6
ldrpcallinitroutine
windbg scripts
wow64exts
debug_flr_image_timestamp
userdump debug
crash analyzer
dumpanalysis
vdtw30.dll
windbg 64 bits dump identify
fnodobfm
the stored exception information can be accessed via .ecxr.
windbg tips
0×80070026
dmitri windbg
gdb teb
nmi_hardware_failure
system_thread_exception_not_handled
system_thread_exception_not_handled (7e)
windbg command
pool allocations have failed
receivelotsacalls
trap frame
vista dr watson
bios disassembly ninjutsu uncovered
citrix tools at pubforum
clock_watchdog_timeout
dump analyzer

- Dmitry Vostokov @ DumpAnalysis.org -

I was reading this weekend a book about overparenting (I’m the father of two) and came across SOS abbreviation used in parenting and education context. Immediately a thought struck me that SOS might also mean two sometimes related conditions:

• - Stressed Operating System
• - Spiking Operating System

May also mean Sinking Operating System (in production environment context).

Any other suggestions?

- Dmitry Vostokov @ DumpAnalysis.org -

The work for Memory Dump Analysis Anthology, Volume 2 is underway and it is natural to use the modular structure of a book heap again for its front cover. Now it is the partial reading list for this year (click to enlarge):

In addition to memory dump allegory the picture also symbolizes kernel / user space split of 4Gb virtual address space :-) Of course, this is just the base image and the book title will be put somewhere on it.

- Dmitry Vostokov @ DumpAnalysis.org -

Many people expressed interest in expanding Practical Foundations of Debugging (x64) and merging it with commented version of Practical Foundations of Debugging (x86) and Reading Windows-based Code. I therefore decided to dedicate some time during the next two months for this task and publish a book. Its main purpose is to help technical support and escalation engineers, testers and software developers without the knowledge of assembly language and C to master all necessary prerequisites to understand and start debugging and crash dump analysis on Windows platforms. It doesn’t require any specific knowledge, fills the gap and lowers the learning curve required for Advanced Windows Debugging and for my own books. It will also serve as a hardware complement to my seminars that I give from time to time. More details will be posted later but for now there are preliminary product details:

• Title: Windows Debugging: Practical Foundations
• Author: Dmitry Vostokov
• Publisher: Opentask (01 February 2009)
• Language: English
• Product Dimensions: 22.86 x 15.24
• ISBN-13: 978-1-906717-10-0
• Paperback: 200 pages

- Dmitry Vostokov @ DumpAnalysis.org -

Data Contents Locality is a comparative pattern that helps not only in identifying the class of the problem but increases our confidence and degree of belief in the specific hypothesis. Suppose we have a database of notes of previous problems. If we see the same or similar data accessed in the new memory dump we might suppose that the issue is similar. If Data Contents Locality is complemented by Code Path Locality (similar partial stack traces and code residues) it even  greater boosts our confidence in suggesting specific troubleshooting steps, recommending fixes and service packs or routing the problem to the next support or development service supply chain (like escalating the issue).

Suppose we got a new kernel memory dump with IRQL_NOT_LESS_OR_EQUAL  (A) bugcheck pointing to our module and we notice the write access to a structure in a nonpaged pool having specific pool tag:

3: kd> .trap 9ee8d9b0
ErrCode = 00000002
eax=85407650 ebx=858f6650 ecx=ffffffff edx=85407648 esi=858f65a8 edi=858f6620
eip=8083df4c esp=9ee8da24 ebp=9ee8da64 iopl=0 nv up ei pl zr na pe nc
cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000 efl=00010246
nt!KeWaitForSingleObject+0x24f:
8083df4c 8919            mov     dword ptr [ecx],ebx  ds:0023:ffffffff=????????

STACK_TEXT: 
9ee8d9b0 8083df4c badb0d00 85407648 00000000 nt!KiTrap0E+0x2a7
9ee8da64 80853f3f 85407648 0000001d 00000000 nt!KeWaitForSingleObject+0×24f
9ee8da7c 8081d45f 865b18d8 854076b0 f4b9e53b nt!KiAcquireFastMutex+0×13
9ee8da88 f4b9e53b 00000004 86940110 85407638 nt!ExAcquireFastMutex+0×20
9ee8daa8 f4b9ed98 85407638 00000000 86940110 driver!Query+0×143
[…]

3: kd> !pool 85407648
Pool page 85407648 region is Nonpaged pool
 85407000 size:   80 previous size:    0  (Allocated)  Mdl
 85407080 size:   30 previous size:   80  (Allocated)  Even (Protected)
 854070b0 size:   28 previous size:   30  (Allocated)  Ntfn
 854070d8 size:   28 previous size:   28  (Allocated)  NtFs
 85407100 size:   28 previous size:   28  (Allocated)  Ntfn
[...]
 85407570 size:   28 previous size:   70  (Allocated)  Ntfn
 85407598 size:   98 previous size:   28  (Allocated)  File (Protected)
*85407630 size:   b0 previous size:   98  (Free ) *DrvA

Dumping the memory address passed to KeWaitForSingleObject shows simple but peculiar pattern:

3: kd> dd 85407648
85407648  ffffffff ffffffff ffffffff ffffffff
85407658  ffffffff ffffffff ffffffff ffffffff
85407668  ffffffff ffffffff ffffffff ffffffff
85407678  ffffffff ffffffff ffffffff ffffffff
85407688  ffffffff ffffffff ffffffff ffffffff
85407698  ffffffff ffffffff ffffffff ffffffff
854076a8  ffffffff ffffffff ffffffff ffffffff
854076b8  ffffffff ffffffff ffffffff ffffffff

We find several similar cases in our database but with different overall call stacks except the topmost wait call. Then we notice that in previous cases there were mutants associated with thread structure and we have the same now:

0: kd> !thread
THREAD 858f65a8 Cid 474c.4530 Teb: 7ffdf000 Win32Thread: bc012410 RUNNING on processor 0
[…]

3: kd> dt /r _KTHREAD 858f65a8 MutantListHead
nt!_KTHREAD
   +0×010 MutantListHead : _LIST_ENTRY [ 0×86773040 - 0×86773040 ]

3: kd> !pool 86773040
Pool page 86773040 region is Nonpaged pool
*86773000 size:   50 previous size:    0  (Allocated) *Muta (Protected)
  Pooltag Muta : Mutant objects
[…]

This narrows the issue to only a few previous cases. In one previous case WaitBlockList associated with a thread structure had 0xffffffff in its pointers. Our block shows the same pattern:

0: kd> dt -r _KTHREAD 858f65a8  WaitBlockList
nt!_KTHREAD
   +0×054 WaitBlockList : 0×858f6650 _KWAIT_BLOCK

0: kd> dt _KWAIT_BLOCK 0x858f6650
nt!_KWAIT_BLOCK
   +0x000 WaitListEntry    : _LIST_ENTRY [ 0x85407650 - 0xffffffff ]
   +0×008 Thread           : 0×858f65a8 _KTHREAD
   +0×00c Object           : 0×85407648
   +0×010 NextWaitBlock    : 0×858f6650 _KWAIT_BLOCK
   +0×014 WaitKey          : 0
   +0×016 WaitType         : 0×1 ”
   +0×017 SpareByte        : 0 ”

We have probably narrowed down the issue to a specific case. Although this doesn’t work always and mostly based on intuition there are spectacular cases where it really helps in troubleshooting. Here is another example where the contents of EDI register from exception context provided specific recommendation hints. When looking at the crash point we see an instance of Wild Code pattern:

0:000> kv
ChildEBP RetAddr  Args to Child             
WARNING: Frame IP not in any known module. Following frames may be wrong.
49ab5bba 00000000 00000000 00000000 00000000 0x60f1011a

0:000> r
eax=38084ff0 ebx=52303340 ecx=963f1416 edx=0000063d esi=baaff395 edi=678c5804
eip=60f1011a esp=5a9d0f48 ebp=49ab5bba iopl=0  nv up ei pl nz na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000  efl=00210206
60f1011a cd01            int     1

0:000> u
60f1011a cd01            int     1
60f1011c cc              int     3
60f1011d 8d              ???
60f1011e c0eb02          shr     bl,2
60f10121 0f840f31cd01    je      62be3236
60f10127 8d              ???
60f10128 c0cc0f          ror     ah,0Fh
60f1012b 0bce            or      ecx,esi

Looking at raw stack data we notice the presence of a specific component that is known to patch the process import table. Applying techniques outlined in Hooked Functions pattern we notice two different 3rd-party components that patched two different modules (kernel32 and user32):

0:000> !chkimg -lo 50 -d !kernel32 -v
Searching for module with expression: !kernel32
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: c:\mss\kernel32.dll\4626487F102000\kernel32.dll
No range specified

Scanning section:    .text
Size: 564709
Range to scan: 77e41000-77ecade5
    77e41ae5-77e41ae9  5 bytes - kernel32!LoadLibraryExW
 [ 6a 34 68 48 7b:e9 16 e5 f4 07 ]
    77e44a8a-77e44a8e  5 bytes - kernel32!WaitNamedPipeW (+0×2fa5)
 [ 8b ff 55 8b ec:e9 71 b5 f9 07 ]
    77e5106a-77e5106e  5 bytes - kernel32!CreateProcessInternalW (+0xc5e0)
[…]
Total bytes compared: 564709(100%)
Number of errors: 49
49 errors : !kernel32 (77e41ae5-77e9aa16)

0:000> u 77e41ae5
kernel32!LoadLibraryExW:
77e41ae5 jmp     7fd90000
77e41aea out     77h,al
77e41aec call    kernel32!_SEH_prolog (77e6b779)
77e41af1 xor     edi,edi
77e41af3 mov     dword ptr [ebp-28h],edi
77e41af6 mov     dword ptr [ebp-2Ch],edi
77e41af9 mov     dword ptr [ebp-20h],edi
77e41afc cmp     dword ptr [ebp+8],edi

0:000> u 7fd90000
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for ComponentA.dll -
7fd90000 jmp     ComponentA!DllUnregisterServer+0×2700 (678c4280)
7fd90005 push    34h
7fd90007 push    offset kernel32!`string’+0xc (77e67b48)
7fd9000c jmp     kernel32!LoadLibraryExW+0×7 (77e41aec)
7fd90011 add     byte ptr [eax],al
7fd90013 add     byte ptr [eax],al
7fd90015 add     byte ptr [eax],al
7fd90017 add     byte ptr [eax],al

0:000> !chkimg -lo 50 -d !user32 -v
Searching for module with expression: !user32
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: c:\mss\user32.dll\45E7BFD692000\user32.dll
No range specified

Scanning section:    .text
Size: 396943
Range to scan: 77381000-773e1e8f
    77383f38-77383f3c  5 bytes - user32!EnumDisplayDevicesW
 [ 8b ff 55 8b ec:e9 c3 c0 82 08 ]
    77384406-7738440a  5 bytes - user32!EnumDisplaySettingsExW (+0×4ce)
 [ 8b ff 55 8b ec:e9 f5 bb 7e 08 ]
    773844d9-773844dd  5 bytes - user32!EnumDisplaySettingsW (+0xd3)
 [ 8b ff 55 8b ec:e9 22 bb 80 08 ]
    7738619b-7738619f  5 bytes - user32!EnumDisplayDevicesA (+0×1cc2)
 [ 8b ff 55 8b ec:e9 60 9e 83 08 ]
    7738e985-7738e989  5 bytes - user32!CreateWindowExA (+0×87ea)
 [ 8b ff 55 8b ec:e9 76 16 8c 08 ]
[…]
Total bytes compared: 396943(100%)
Number of errors: 119
119 errors : !user32 (77383f38-773c960c)

0:000> u 77383f38
user32!EnumDisplayDevicesW:
77383f38 e9c3c08208      jmp     7fbb0000
77383f3d 81ec58030000    sub     esp,358h
77383f43 a1ac243e77      mov     eax,dword ptr [user32!__security_cookie (773e24ac)]
77383f48 8b5508          mov     edx,dword ptr [ebp+8]
77383f4b 83a5acfcffff00  and     dword ptr [ebp-354h],0
77383f52 53              push    ebx
77383f53 56              push    esi
77383f54 8b7510          mov     esi,dword ptr [ebp+10h]

0:000> u 7fbb0000
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for ComponentB.dll -
7fbb0000 e91b43d5e5      jmp     ComponentB+0×4320 (65904320)
7fbb0005 8bff            mov     edi,edi
7fbb0007 55              push    ebp
7fbb0008 8bec            mov     ebp,esp
7fbb000a e92e3f7df7      jmp     user32!EnumDisplayDevicesW+0×5 (77383f3d)
7fbb000f 0000            add     byte ptr [eax],al
7fbb0011 0000            add     byte ptr [eax],al
7fbb0013 0000            add     byte ptr [eax],al

Which one should we try to eliminate first to test our assumption that they somehow resulted in application faults? Looking at register context again we see that one specific register (EDI) has a value that lies in ComponentA address range:

0:000> r
eax=38084ff0 ebx=52303340 ecx=963f1416 edx=0000063d esi=baaff395 edi=678c5804
eip=60f1011a esp=5a9d0f48 ebp=49ab5bba iopl=0  nv up ei pl nz na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000 efl=00210206
60f1011a cd01            int     1

0:000> lm
start    end        module name
00400000 01901000   Application
[...]
678c0000 6791d000   ComponentA   ComponentA.DLL
[…]

- Dmitry Vostokov @ DumpAnalysis.org -

Not My Version is another basic pattern of DLL Hell variety. It is when we look at the component timestamps and paths and realize that that one of the modules from the production environment is older than we had during development and testing. The lmft WinDbg command will produce the necessary output. If there are many modules we might want to create a CAD graph (Component Age Diagram) to spot anomalies. Component version check is one of the basic troubleshooting and system administration activities that will be fully illustrated in the forthcoming book “Crash Dump Analysis for System Administrators and Support Engineers” (ISBN-13: 978-1-906717-02-5). Here is one example (module start and end load addresses are removed for visual clarity):

0:000> kL
Child-SP          RetAddr           Call Site
00000000`0012fed8 00000001`40001093 MyDLL!fnMyDLL
00000000`0012fee0 00000001`40001344 2DLLs+0×1093
00000000`0012ff10 00000000`773acdcd 2DLLs+0×1344
00000000`0012ff60 00000000`774fc6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d


0:000> lmft
module name
MyDLL    C:\OLD\MyDLL.dll Wed Jun 18 14:49:13 2004
user32   C:\Windows\System32\user32.dll Thu Feb 15 05:22:33 2007
kernel32 C:\Windows\System32\kernel32.dll Thu Nov 02 11:14:48 2006
ntdll    C:\Windows\System32\ntdll.dll Thu Nov 02 11:16:02 2006
2DLLs    C:\2DLLs\2DLLs.exe Thu Jun 19 10:46:44 2008 (485A2B04)
uxtheme  C:\Windows\System32\uxtheme.dll Thu Nov 02 11:15:07 2006
rpcrt4   C:\Windows\System32\rpcrt4.dll Tue Jul 17 05:21:15 2007
lpk      C:\Windows\System32\lpk.dll Thu Nov 02 11:12:33 2006
oleaut32 C:\Windows\System32\oleaut32.dll Thu Dec 06 05:09:35 2007
usp10    C:\Windows\System32\usp10.dll Thu Nov 02 11:15:03 2006
ole32    C:\Windows\System32\ole32.dll Thu Nov 02 11:14:31 2006
advapi32 C:\Windows\System32\advapi32.dll Thu Nov 02 11:11:35 2006
gdi32    C:\Windows\System32\gdi32.dll Thu Feb 21 04:40:51 2008
msvcrt   C:\Windows\System32\msvcrt.dll Thu Nov 02 11:13:37 2006
imm32    C:\Windows\System32\imm32.dll Thu Nov 02 11:13:15 2006
msctf    C:\Windows\System32\msctf.dll Thu Nov 02 11:13:42 2006

This pattern should be checked when we have instances of Module Variety and, especially, Duplicated Module. Note that this pattern can also easily become an anti-pattern when applied to an unknown component: Alien Component.

- Dmitry Vostokov @ DumpAnalysis.org -

In addition to Module Variety there is another DLL Hell pattern that I call Duplicated Module. Here the same module is loaded at least twice and we can detect this when we see the module load address appended to its name in the output of lm commands (this is done to make the name of the module unique):

0:000> lm
start    end        module name
00b20000 0147f000   MSO_b20000
30000000 309a7000   EXCEL
30c90000 31848000   mso
71c20000 71c32000   tsappcmp
745e0000 7489e000   msi  
76290000 762ad000   imm32 
76b70000 76b7b000   psapi            
76f50000 76f63000   secur32            
77380000 77411000   user32
77670000 777a9000   ole32
77ba0000 77bfa000   msvcrt
77c00000 77c48000   gdi32          
77c50000 77cef000   rpcrt4           
77da0000 77df2000   shlwapi            
77e40000 77f42000   kernel32
77f50000 77feb000   advapi32           
7c800000 7c8c0000   ntdll

Usually his happens when the DLL is loaded from different locations. It can be exactly the same DLL version. The problems usually surface when there are different DLL versions and the new code loads the old version of the DLL and uses it. This may result in interface incompatibility issues and ultimately in application fault like an access violation.

In order to provide a dump to play with I created a small toy program called 2DLLs to model the worst case scenario similar to the one I encountered in a production environment a couple of days ago. The program periodically loads MyDLL module to call one of its functions. Unfortunately in one place it uses hardcoded relative path:

HMODULE hLib = LoadLibrary(L".\\DLL\\MyDLL.dll");

and in another place it relies on DLL search order:

hLib = LoadLibrary(L".\\MyDLL.dll");

PATH variable directories are used for search if this DLL was not found in other locations specified by DLL search order. We see that the problem can happen when another application is installed which uses the old version of that DLL and modifies PATH variable to point to its location. To model interface incompatibility I compiled the version of MyDLL that causes NULL pointer access violation when the same function is called from it. The DLL was placed into a separate folder and the PATH variable was modified to reference that folder:

C:\>set PATH=C:\OLD;%PATH%

The application crashes and the installed default postmortem debugger (CDB) saves its crash dump. If we open it we would see that it crashed in MyDLL_1e60000 module which should trigger suspicion:

0:000> r
rax=0000000001e61010 rbx=0000000000000000 rcx=0000775dcac00000
rdx=0000000000000000 rsi=0000000000000006 rdi=0000000000001770
rip=0000000001e61010 rsp=000000000012fed8 rbp=0000000000000000
 r8=0000000000000000  r9=000000000012fd58 r10=0000000000000001
r11=000000000012fcc0 r12=0000000000000000 r13=0000000000000002
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl nz na pe nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010200
MyDLL_1e60000!fnMyDLL:
00000000`01e61010 c704250000000000000000 mov dword ptr [0],0 ds:00000000`00000000=????????

0:000> kL
Child-SP          RetAddr           Call Site
00000000`0012fed8 00000001`40001093 MyDLL_1e60000!fnMyDLL
00000000`0012fee0 00000001`40001344 2DLLs+0×1093
00000000`0012ff10 00000000`773acdcd 2DLLs+0×1344
00000000`0012ff60 00000000`774fc6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

Looking at the list of modules we see two versions of MyDLL loaded from two different folders:

0:000> lm
start             end                 module name
00000000`01e60000 00000000`01e71000   MyDLL_1e60000
00000000`772a0000 00000000`7736a000   user32
00000000`77370000 00000000`774a1000   kernel32
00000000`774b0000 00000000`7762a000   ntdll
00000001`40000000 00000001`40010000   2DLLs
00000001`80000000 00000001`80011000   MyDLL
000007fe`fc9e0000 000007fe`fca32000   uxtheme
000007fe`fe870000 000007fe`fe9a9000   rpcrt4
000007fe`fe9b0000 000007fe`fe9bc000   lpk
000007fe`fea10000 000007fe`feae8000   oleaut32
000007fe`fecd0000 000007fe`fed6a000   usp10
000007fe`fedd0000 000007fe`fefb0000   ole32
000007fe`fefb0000 000007fe`ff0af000   advapi32
000007fe`ff0d0000 000007fe`ff131000   gdi32
000007fe`ff2e0000 000007fe`ff381000   msvcrt
000007fe`ff390000 000007fe`ff3b8000   imm32
000007fe`ff4b0000 000007fe`ff5b4000   msctf

0:000> lmv m MyDLL_1e60000
start             end                 module name
00000000`01e60000 00000000`01e71000   MyDLL_1e60000
    Loaded symbol image file: MyDLL.dll
    Image path: C:\OLD\MyDLL.dll
    Image name: MyDLL.dll
    Timestamp:        Wed Jun 18 14:49:13 2008 (48591259)
[…]

0:000> lmv m MyDLL
start             end                 module name
00000001`80000000 00000001`80011000   MyDLL
    Image path: C:\2DLLs\DLL\MyDLL.dll
    Image name: MyDLL.dll
    Timestamp:        Wed Jun 18 14:50:56 2008 (485912C0)
[...]

We can also see that the old version of MyDLL was the last loaded DLL:

0:000> !dlls -l

0x002c2680: C:\2DLLs\2DLLs.exe
      Base   0x140000000  EntryPoint  0x1400013b0  Size        0x00010000
      Flags  0x00004000  LoadCount   0x0000ffff  TlsIndex    0x00000000
             LDRP_ENTRY_PROCESSED

[...]

0x002ea9b0: C:\2DLLs\DLL\MyDLL.dll
      Base   0x180000000  EntryPoint  0x1800013d0  Size        0x00011000
      Flags  0x00084004  LoadCount   0x00000001  TlsIndex    0x00000000
             LDRP_IMAGE_DLL
             LDRP_ENTRY_PROCESSED
             LDRP_PROCESS_ATTACH_CALLED

[...]

0x002ec430: C:\OLD\MyDLL.dll
      Base   0×01e60000  EntryPoint  0×01e613e0  Size        0×00011000
      Flags  0×00284004  LoadCount   0×00000001  TlsIndex    0×00000000
             LDRP_IMAGE_DLL
             LDRP_ENTRY_PROCESSED
             LDRP_PROCESS_ATTACH_CALLED
             LDRP_IMAGE_NOT_AT_BASE

We can also see that the PATH variable points to its location and this might explain why it was loaded:

0:000> !peb
PEB at 000007fffffd6000
[...]
Path=C:\OLD;C:\Windows\system32;C:\Windows;[…]
[…]

We might think that the module having address in its name was loaded the last but this is not true. If we save another copy of the dump from the existing one using .dump command and load the new dump file we would see that order of the module names is reversed:

0:000> kL
Child-SP          RetAddr           Call Site
00000000`0012fed8 00000001`40001093 MyDLL!fnMyDLL
00000000`0012fee0 00000001`40001344 2DLLs+0×1093
00000000`0012ff10 00000000`773acdcd 2DLLs+0×1344
00000000`0012ff60 00000000`774fc6e1 kernel32!BaseThreadInitThunk+0xd
00000000`0012ff90 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:000> lm
start             end                 module name
00000000`01e60000 00000000`01e71000   MyDLL
00000000`772a0000 00000000`7736a000   user32
00000000`77370000 00000000`774a1000   kernel32
00000000`774b0000 00000000`7762a000   ntdll
00000001`40000000 00000001`40010000   2DLLs
00000001`80000000 00000001`80011000   MyDLL_180000000
000007fe`fc9e0000 000007fe`fca32000   uxtheme
000007fe`fe870000 000007fe`fe9a9000   rpcrt4
000007fe`fe9b0000 000007fe`fe9bc000   lpk
000007fe`fea10000 000007fe`feae8000   oleaut32
000007fe`fecd0000 000007fe`fed6a000   usp10
000007fe`fedd0000 000007fe`fefb0000   ole32
000007fe`fefb0000 000007fe`ff0af000   advapi32
000007fe`ff0d0000 000007fe`ff131000   gdi32
000007fe`ff2e0000 000007fe`ff381000   msvcrt
000007fe`ff390000 000007fe`ff3b8000   imm32
000007fe`ff4b0000 000007fe`ff5b4000   msctf

0:000> !dlls -l

[...]

0x002ec430: C:\OLD\MyDLL.dll
      Base   0×01e60000  EntryPoint  0×01e613e0  Size        0×00011000
      Flags  0×00284004  LoadCount   0×00000001  TlsIndex    0×00000000
             LDRP_IMAGE_DLL
             LDRP_ENTRY_PROCESSED
             LDRP_PROCESS_ATTACH_CALLED
             LDRP_IMAGE_NOT_AT_BASE

The postprocessed dump file can be downloaded from FTP to play with:

ftp://dumpanalysis.org/pub/CDAPatternDuplicatedModule.zip 

- Dmitry Vostokov @ DumpAnalysis.org -

Analysis of computer memory snapshots (memory dumps) and their evolution is the domain of memoretics. Computer memory semiotics (memiotics or memosemiotics) is the branch of memoretics that studies the interpretation of computer memory, its meaning, signs and symbols.

- Dmitry Vostokov @ DumpAnalysis.org -     

Looking at computer memory visual images combined with listening to the incredible nostalgic music composed by Oystein Sevag is highly recommended to relieve stress while immersing yourself in the vast depths of memory hierarchy. I really like “Painful Love” tracks. Is love and passion for programming painful?…

Visual

Link

- Dmitry Vostokov @ DumpAnalysis.org -

Mistake #2 - Not seeing semantic and pragmatic inconsistencies

Why would FreeHeap need a file name? See Incorrect Stack Trace pattern case study for semantic inconsistency. Why is this function on the stack trace

dll!exit+0x10,834

67,636 bytes long (0×10,834 in decimal)?  

The latter is an example of pragmatic inconsistency and the answer is that we don’t have symbols and the name appears from the DLL export table. The code on the stack has nothing to do with exit action when proper symbols are applied.

Another example. The memory dump of a hanging process has only one thread and it is waiting for an event. Is this the problem in ThreadProc and application logic or in the fact that _endthreadex was called when the thread was created?

STACK_TEXT: 
0379fa50 7642dcea ntdll!NtWaitForMultipleObjects+0x15
0379faec 75e08f76 kernel32!WaitForMultipleObjectsEx+0x11d
0379fb40 75e08fbf user32!RealMsgWaitForMultipleObjectsEx+0x14d
0379fb5c 00f6b45d user32!MsgWaitForMultipleObjects+0x1f
0379fba8 752e29bb application!ThreadProc+0xad
0379fbe0 752e2a47 msvcr80!_endthreadex+0×3b
0379fbe8 7649e3f3 msvcr80!_endthreadex+0xc7
0379fbf4 7773cfed kernel32!BaseThreadInitThunk+0xe
0379fc34 7773d1ff ntdll!__RtlUserThreadStart+0×23
0379fc4c 00000000 ntdll!_RtlUserThreadStart+0×1b

The latter assumption is wrong. The presence of _endthreadex stems from the fact that its address was pushed to let a user thread procedure to automatically call it upon the normal function return:  

0:000> u 752e29bb
msvcr80!_endthreadex+0x3b:
752e29bb 50              push    eax
752e29bc e8bfffffff      call    msvcr80!_endthreadex (752e2980)
752e29c1 8b45ec          mov     eax,dword ptr [ebp-14h]
752e29c4 8b08            mov     ecx,dword ptr [eax]
752e29c6 8b09            mov     ecx,dword ptr [ecx]
752e29c8 894de4          mov     dword ptr [ebp-1Ch],ecx
752e29cb 50              push    eax
752e29cc 51              push    ecx

A thread procedure passed to thread creation API call can be any C function. How would a C/C++ compiler understand that it needs to generate a call to thread exit API especially if ThreadProc is named FooBar and resides in a different compilation unit or a library? It seems logical that the runtime environment provides such an automatic return address dynamically. Also why and how _endthreadex knows about our custom ThreadProc to call it? Looks like inconsistency. The ability to see and reason about them is very important skill in memory dump analysis and debugging. The lack of sufficient unmanaged code programming experience might partly explain many analysis mistakes.

- Dmitry Vostokov @ DumpAnalysis.org -

From “coordinated coping” to “what feels like chaos can feel like a dance - a fast one” - say Francoise Tourniaire and Richard Farrell in their infuential book “The Art of Software Support”. I totally agree and from my observation the most successful (not stressful) people in software support are “dancing” when dealing with everyday and hot customer issues. You see them literally thriving on inherent chaos. Truly multitaskers and even multithreaders!

- Dmitry Vostokov @ DumpAnalysis.org -