Software Diagnostics Library » Crash Dump Patterns

Crash Dump Analysis Patterns (Part 224)

Saturday, April 25th, 2015

When analyzing Spiking Threads across Snapshot Collection we are interested in finding a module (or a function) that was most likely responsible (for example, “looping” inside). Here we can compare the same thread stack trace from different memory dumps and find their Variable Subtrace. For such subtraces we have changes in kv-style output: in return addresses, stack frame values, and possible arguments. The call site that starts the variable subtrace is the most likely candidate (subject to the number of snapshots). For example, consider the following pseudo code:

ModuleA!start()
{
    ModuleA!func1();
}

ModuleA!func1()
{
    ModuleB!func2();
}

ModuleB!func2()
{
    while (…)
    {
        ModuleB!func3();
    }
}

ModuleB!func3()
{
    ModuleB!func4();
}

ModuleB!func4()
{
    ModuleB!func5();
}

ModuleB!func5()
{
    // ...
}

Here, the variable stack trace part will correspond to ModuleB frames. The memory dump can be saved anywhere inside the “while” loop and down the calls, and the last variable return address down the stack trace will belong to ModuleB!func2 address range. The non-variable part will start with ModuleA!func1 address range:

// snapshot 1

RetAddr ModuleB!func4+0×20 ModuleB!func3+0×10 ModuleB!func2+0×40 ModuleA!func1+0×10 ModuleA!start+0×300

// snapshot 2

RetAddr ModuleB!func2+0×20 ModuleA!func1+0×10 ModuleA!start+0×300

// snapshot 3

RetAddr ModuleB!func3+0×20 ModuleB!func2+0×40 ModuleA!func1+0×10 ModuleA!start+0×300

To illustrate this analysis pattern we adopted Memory Cell Diagram (MCD) approach from Accelerated Disassembly, Reconstruction and Reversing training and introduce here Abstract Stack Trace Notation (ASTN) diagrams where different colors are used for different modules and changes are highlighted with different fill patterns. The following three ASTN diagrams from subsequently saved process memory dumps illustrate real stack traces we analyzed some time ago. We see that the variable subtrace contains only the 3rd-party ModuleB calls. Moreover, the loop is possibly contained inside ModuleB because all ModuleA frames are non-variable including Child-SP and Args column values.

If we had ASTN diagrams below instead we would have concluded that the loop was in ModuleA with changes in ModuleB columns as an execution side effect:

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

Posted in Abstract Stack Trace Notation, Crash Dump Analysis, Crash Dump Patterns, Memory Cell Diagrams, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 223)

Saturday, March 7th, 2015

Sometimes we can see signs of Crashed Processes in kernel and complete memory dumps. By crashes we mean the sudden disappearance of processes from Task Manager, for example. In memory dumps we can still see such processes as Zombie Processes. Special Processes found in the process list may help to select the possible candidate among many Zombie Processes. If a process is supposed to be launched only once (like a service) but found several times as Zombie Process and also as a normal process later in the process list (for example, as Last Object), then this may point to possible past crashes (or silent terminations). We also have a similar trace analysis pattern: Singleton Event. The following example illustrates both signs:

0: kd> !process 0 0

[...]

PROCESS fffffa80088a5640 SessionId: 0 Cid: 2184 Peb: 7fffffd7000 ParentCid: 0888 DirBase: 381b8000 ObjectTable: 00000000 HandleCount: 0. Image: WerFault.exe

PROCESS fffffa8007254b30 SessionId: 0 Cid: 20ac Peb: 7fffffdf000 ParentCid: 02cc DirBase: b3306000 ObjectTable: 00000000 HandleCount: 0. Image: ServiceA.exe

[...]

PROCESS fffffa8007fe2b30 SessionId: 0 Cid: 2a1c Peb: 7fffffdf000 ParentCid: 02cc DirBase: 11b649000 ObjectTable: fffff8a014939530 HandleCount: 112. Image: ServiceA.exe

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

Posted in Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 222)

Saturday, February 28th, 2015

Software Exception is added for completeness of pattern discourse. We mentioned it a few times before, for example, in Activation Context, Exception Module, Missing Component (static linkage), Self-Dump, Stack Overflow (software implementation), and Translated Exception patterns. Typical example of software exceptions is C++ Exception pattern.

Software exceptions, such as not enough memory, are different from the so-called hardware exceptions by being predictable, synchronous, and detected by software code itself. Hardware exceptions such as divide by zero, access violation, and memory protection, on the contrary, are unpredictable, and detected by hardware. Of course, it is possible to do some checks before code execution, and then throw a software exception or some diagnostic message for a would be hardware exception. See, for example, Self-Diagnosis pattern for user mode and its corresponding equivalent for kernel mode.

In Windows memory dumps we may see RaiseException call in user space stack trace, such as from Data Correlation pattern example:

0:000> kL ChildEBP RetAddr 0012e950 78158e89 kernel32!RaiseException+0×53 0012e988 7830770c msvcr80!_CxxThrowException+0×46 0012e99c 783095bc mfc80u!AfxThrowMemoryException+0×19 0012e9b4 02afa8ca mfc80u!operator new+0×27 0012e9c8 02b0992f ModuleA!std::_Allocate<…>+0×1a 0012e9e0 02b09e7c ModuleA!std::vector >::vector >+0×3f […]

When looking for Multiple or Hidden Exceptions we may also want to check for such calls.

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging | 3 Comments »

Crash Dump Analysis Patterns (Part 221)

Saturday, February 21st, 2015

Corrupt Structure is added for completeness of pattern discourse. We mentioned it a few times, for example, in Self-Diagnosis (kernel mode), and Critical Section Corruption. Typical signs of the corrupt structure include:

- Regular Data such as ASCII and UNICODE fragments over substructures and pointer areas
- Large values where you expect small and vice versa
- User space address values where we expect kernel space and vice versa
- Malformed and partially zeroed _LIST_ENTRY data (see exercise C3 for linked list navigation)
- Memory read errors for pointer dereferences or inaccessible memory indicators (??)
- Memory read error at the end of the linked list while traversing structures

0: kd> dt _ERESOURCE ffffd0002299f830 ntdll!_ERESOURCE +0x000 SystemResourcesList : _LIST_ENTRY [ 0xffffc000`07b64800 - 0xffffe000`02a79970 ] +0x010 OwnerTable : 0xffffe000`02a79940 _OWNER_ENTRY +0x018 ActiveCount : 0n0 +0x01a Flag : 0 +0x01a ReservedLowFlags : 0 '' +0x01b WaiterPriority : 0 '' +0x020 SharedWaiters : 0x00000000`00000001 _KSEMAPHORE +0x028 ExclusiveWaiters : 0xffffe000`02a79a58 _KEVENT +0x030 OwnerEntry : _OWNER_ENTRY +0x040 ActiveEntries : 0 +0x044 ContentionCount : 0 +0×048 NumberOfSharedWaiters : 0×7b64800 +0×04c NumberOfExclusiveWaiters : 0xffffc000 +0×050 Reserved2 : (null) +0×058 Address : 0xffffd000`2299f870 Void +0×058 CreatorBackTraceIndex : 0xffffd000`2299f870 +0×060 SpinLock : 1

0: kd> dt _ERESOURCE ffffd0002299d830 ntdll!_ERESOURCE +0×000 SystemResourcesList : _LIST_ENTRY [ 0×000001e0`00000280 - 0×00000000`00000004 ] +0×010 OwnerTable : 0×00000000`0000003c _OWNER_ENTRY +0×018 ActiveCount : 0n0 +0×01a Flag : 0 +0×01a ReservedLowFlags : 0 ” +0×01b WaiterPriority : 0 ” +0×020 SharedWaiters : 0×0000003c`000001e0 _KSEMAPHORE +0×028 ExclusiveWaiters : (null) +0×030 OwnerEntry : _OWNER_ENTRY +0×040 ActiveEntries : 0 +0×044 ContentionCount : 0×7f +0×048 NumberOfSharedWaiters : 0×7f +0×04c NumberOfExclusiveWaiters : 0×7f +0×050 Reserved2 : 0×00000001`00000001 Void +0×058 Address : 0×00000000`00000005 Void +0×058 CreatorBackTraceIndex : 5 +0×060 SpinLock : 0

However, we need to be sure that we supplied the correct pointer to dt WinDbg command. One of the signs that the pointer was incorrect are memory read errors or all zeroes:

0: kd> dt _ERESOURCE ffffd000229af830 ntdll!_ERESOURCE +0x000 SystemResourcesList : _LIST_ENTRY [ 0x00000000`00000000 - 0x00000000`00000000 ] +0x010 OwnerTable : (null) +0x018 ActiveCount : 0n0 +0x01a Flag : 0 +0x01a ReservedLowFlags : 0 '' +0x01b WaiterPriority : 0 '' +0x020 SharedWaiters : (null) +0x028 ExclusiveWaiters : (null) +0x030 OwnerEntry : _OWNER_ENTRY +0x040 ActiveEntries : 0 +0x044 ContentionCount : 0 +0x048 NumberOfSharedWaiters : 0 +0x04c NumberOfExclusiveWaiters : 0 +0x050 Reserved2 : (null) +0x058 Address : (null) +0x058 CreatorBackTraceIndex : 0 +0x060 SpinLock : 0

0: kd> dt _ERESOURCE ffffd00022faf830 ntdll!_ERESOURCE +0x000 SystemResourcesList : _LIST_ENTRY +0x010 OwnerTable : ???? +0x018 ActiveCount : ?? +0x01a Flag : ?? +0x01a ReservedLowFlags : ?? +0x01b WaiterPriority : ?? +0x020 SharedWaiters : ???? +0x028 ExclusiveWaiters : ???? +0x030 OwnerEntry : _OWNER_ENTRY +0x040 ActiveEntries : ?? +0x044 ContentionCount : ?? +0x048 NumberOfSharedWaiters : ?? +0x04c NumberOfExclusiveWaiters : ?? +0x050 Reserved2 : ???? +0x058 Address : ???? +0x058 CreatorBackTraceIndex : ?? +0x060 SpinLock : ?? Memory read error ffffd00022faf890

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

Posted in Core Dump Analysis, Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 220)

Tuesday, February 17th, 2015

Sometimes, due to optimization or indeterminate stack trace reconstruction, we may not see all stack trace frames. In some case it is possible to reconstruct such Hidden Calls. For example, we have the following unmanaged Stack Trace of CLR Thread:

0:000> k ChildEBP RetAddr 0011d6b8 66fdee7c mscorwks!JIT_IsInstanceOfClass+0xd 0011d6cc 67578500 PresentationCore_ni!`string'+0x4a2bc 0011d6e0 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778500) 0011d6f4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527) 0011d708 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d71c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d730 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d744 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d758 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d76c 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d780 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527) 0011d794 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d7a8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d7bc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d7d0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d7e4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d7f8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d80c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d820 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d834 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d848 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d85c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d870 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d884 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d898 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d8ac 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d8c0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d8d4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d8e8 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d8fc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527) 0011d910 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d924 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d938 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d94c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d960 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d974 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d988 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d99c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d9b0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d9c4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d9d8 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011d9ec 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527) 0011da00 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da14 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da28 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da3c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da50 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da64 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da78 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011da8c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011daa0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dab4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dac8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dadc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011daf0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db04 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db18 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db2c 67578527 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db40 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x778527) 0011db54 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db68 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db7c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011db90 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dba4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dbb8 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dbcc 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dbe0 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dbf4 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dc08 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dc1c 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dc30 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dc44 6757850d PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) 0011dc58 66fc3282 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x77850d) *** WARNING: Unable to verify checksum for PresentationFramework.ni.dll 0011dd28 662a75e6 PresentationCore_ni!`string'+0x2e6c2 0011de08 662190a0 PresentationFramework_ni+0x2675e6 0011dffc 66fc35e2 PresentationFramework_ni+0x1d90a0 0011e0ec 66fd9dad PresentationCore_ni!`string'+0x2ea22 0011e214 66fe0459 PresentationCore_ni!`string'+0x451ed 0011e238 66fdfd40 PresentationCore_ni!`string'+0x4b899 0011e284 66fdfc9b PresentationCore_ni!`string'+0x4b180 *** WARNING: Unable to verify checksum for WindowsBase.ni.dll 0011e2b0 723ca31a PresentationCore_ni!`string'+0x4b0db 0011e2cc 723ca20a WindowsBase_ni+0x9a31a 0011e30c 723c8384 WindowsBase_ni+0x9a20a 0011e330 723cd26d WindowsBase_ni+0x98384 0011e368 723cd1f8 WindowsBase_ni+0x9d26d 0011e380 72841b4c WindowsBase_ni+0x9d1f8 0011e390 728589ec mscorwks!CallDescrWorker+0x33 0011e410 72865acc mscorwks!CallDescrWorkerWithHandler+0xa3 0011e54c 72865aff mscorwks!MethodDesc::CallDescr+0x19c 0011e568 72865b1d mscorwks!MethodDesc::CallTargetWorker+0x1f 0011e580 728bd9c8 mscorwks!MethodDescCallSite::CallWithValueTypes+0x1a 0011e74c 728bdb1e mscorwks!ExecuteCodeWithGuaranteedCleanupHelper+0x9f *** WARNING: Unable to verify checksum for mscorlib.ni.dll 0011e7fc 68395887 mscorwks!ReflectionInvocation::ExecuteCodeWithGuaranteedCleanup+0x10f 0011e818 683804b5 mscorlib_ni+0x235887 0011e830 723cd133 mscorlib_ni+0x2204b5 0011e86c 723c7a27 WindowsBase_ni+0x9d133 0011e948 723c7d13 WindowsBase_ni+0x97a27 0011e984 723ca4fe WindowsBase_ni+0x97d13 0011e9d0 723ca42a WindowsBase_ni+0x9a4fe 0011e9f0 723ca31a WindowsBase_ni+0x9a42a 0011ea0c 723ca20a WindowsBase_ni+0x9a31a 0011ea4c 723c8384 WindowsBase_ni+0x9a20a 0011ea70 723c74e1 WindowsBase_ni+0x98384 0011eaac 723c7430 WindowsBase_ni+0x974e1 0011eadc 723c9b6c WindowsBase_ni+0x97430 0011eb2c 757462fa WindowsBase_ni+0x99b6c 0011eb58 75746d3a user32!InternalCallWinProc+0x23 0011ebd0 757477c4 user32!UserCallWinProcCheckWow+0x109 0011ec30 7574788a user32!DispatchMessageWorker+0x3bc 0011ec40 0577304e user32!DispatchMessageW+0xf WARNING: Frame IP not in any known module. Following frames may be wrong. 0011ec5c 723c7b24 0x577304e 0011eccc 723c71f9 WindowsBase_ni+0x97b24 0011ecd8 723c719c WindowsBase_ni+0x971f9 0011ece4 6620f07e WindowsBase_ni+0x9719c 0011ecf0 6620e37f PresentationFramework_ni+0x1cf07e 0011ed14 661f56d6 PresentationFramework_ni+0x1ce37f 0011ed24 661f5699 PresentationFramework_ni+0x1b56d6 0011ed80 72841b4c PresentationFramework_ni+0x1b5699 0011eda0 72841b4c mscorwks!CallDescrWorker+0x33 0011edb0 728589ec mscorwks!CallDescrWorker+0x33 0011ee30 72865acc mscorwks!CallDescrWorkerWithHandler+0xa3 0011ef6c 72865aff mscorwks!MethodDesc::CallDescr+0x19c 0011ef88 72865b1d mscorwks!MethodDesc::CallTargetWorker+0x1f 0011efa0 728fef01 mscorwks!MethodDescCallSite::CallWithValueTypes+0x1a 0011f104 728fee21 mscorwks!ClassLoader::RunMain+0x223 0011f36c 728ff33e mscorwks!Assembly::ExecuteMainMethod+0xa6 0011f83c 728ff528 mscorwks!SystemDomain::ExecuteMainMethod+0x45e 0011f88c 728ff458 mscorwks!ExecuteEXE+0x59 0011f8d4 70aef4f3 mscorwks!_CorExeMain+0x15c 0011f90c 70b77efd mscoreei!_CorExeMain+0x10a 0011f924 70b74de3 mscoree!ShellShim__CorExeMain+0x7d 0011f92c 754c338a mscoree!_CorExeMain_Exported+0x8 0011f938 77659f72 kernel32!BaseThreadInitThunk+0xe 0011f978 77659f45 ntdll!__RtlUserThreadStart+0x70 0011f990 00000000 ntdll!_RtlUserThreadStart+0x1b

Its Managed Stack Trace is the following:

0:000> !CLRStack OS Thread Id: 0x1520 (0) ESP EIP 0011e7a0 728493a4 [HelperMethodFrame_PROTECTOBJ: 0011e7a0] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object) 0011e808 68395887 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 0011e824 683804b5 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) 0011e83c 723cd133 System.Windows.Threading.DispatcherOperation.Invoke() 0011e874 723c7a27 System.Windows.Threading.Dispatcher.ProcessQueue() 0011e950 723c7d13 System.Windows.Threading.Dispatcher.WndProcHook(IntPtr, Int32, IntPtr, IntPtr, Boolean ByRef) 0011e99c 723ca4fe MS.Win32.HwndWrapper.WndProc(IntPtr, Int32, IntPtr, IntPtr, Boolean ByRef) 0011e9e8 723ca42a MS.Win32.HwndSubclass.DispatcherCallbackOperation(System.Object) 0011e9f8 723ca31a System.Windows.Threading.ExceptionWrapper.InternalRealCall(System.Delegate, System.Object, Boolean) 0011ea1c 723ca20a System.Windows.Threading.ExceptionWrapper.TryCatchWhen(System.Object, System.Delegate, System.Object, Boolean, System.Delegate) 0011ea64 723c8384 System.Windows.Threading.Dispatcher.WrappedInvoke(System.Delegate, System.Object, Boolean, System.Delegate) 0011ea84 723c74e1 System.Windows.Threading.Dispatcher.InvokeImpl(System.Windows.Threading.DispatcherPriority, System.TimeSpan, System.Delegate, System.Object, Boolean) 0011eac8 723c7430 System.Windows.Threading.Dispatcher.Invoke(System.Windows.Threading.DispatcherPriority, System.Delegate, System.Object) 0011eaec 723c9b6c MS.Win32.HwndSubclass.SubclassWndProc(IntPtr, Int32, IntPtr, IntPtr) 0011ec74 00270b04 [NDirectMethodFrameStandalone: 0011ec74] MS.Win32.UnsafeNativeMethods.DispatchMessage(System.Windows.Interop.MSG ByRef) 0011ec84 723c7b24 System.Windows.Threading.Dispatcher.PushFrameImpl(System.Windows.Threading.DispatcherFrame) 0011ecd4 723c71f9 System.Windows.Threading.Dispatcher.PushFrame(System.Windows.Threading.DispatcherFrame) 0011ece0 723c719c System.Windows.Threading.Dispatcher.Run() 0011ecec 6620f07e System.Windows.Application.RunDispatcher(System.Object) 0011ecf8 6620e37f System.Windows.Application.RunInternal(System.Windows.Window) 0011ed1c 661f56d6 System.Windows.Application.Run(System.Windows.Window) 0011ed2c 661f5699 System.Windows.Application.Run() [...]

Caller-n-Callee traces also don’t reveal anything more:

Thread 0 Current frame: mscorwks!JIT_IsInstanceOfClass+0xd ChildEBP RetAddr Caller,Callee 0011d6b8 66fdee7c (MethodDesc 0x66ee2954 +0x3c MS.Internal.DeferredElementTreeState.GetLogicalParent(System.Windows.DependencyObject, MS.Internal.DeferredElementTreeState)), calling mscorwks!JIT_IsInstanceOfClass 0011d6cc 67578500 (MethodDesc 0x66ee1270 +0x110 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee2954 +0 MS.Internal.DeferredElementTreeState.GetLogicalParent(System.Windows.DependencyObject, MS.Internal.DeferredElementTreeState)) 0011d6e0 67578527 (MethodDesc 0x66ee1270 +0x137 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)) 0011d6f4 6757850d (MethodDesc 0x66ee1270 +0x11d MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)) 0011d708 6757850d (MethodDesc 0x66ee1270 +0x11d MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)) 0011d71c 6757850d (MethodDesc 0x66ee1270 +0x11d MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)), calling (MethodDesc 0x66ee1270 +0 MS.Internal.UIElementHelper.InvalidateAutomationAncestors(System.Windows.DependencyObject)) [...]

However, if we check the return address for Top Module mscorwks (66fdee7c) we will see a call possibly related to 3D processing:

0:000> k ChildEBP RetAddr 0011d6b8 66fdee7c mscorwks!JIT_IsInstanceOfClass+0xd 0011d6cc 67578500 PresentationCore_ni!`string’+0×4a2bc 0011d6e0 67578527 PresentationCore_ni!`string’ <PERF> (PresentationCore_ni+0×778500) 0011d6f4 6757850d PresentationCore_ni!`string’ <PERF> (PresentationCore_ni+0×778527) […]

0:000> ub 66fdee7c PresentationCore_ni!`string'+0x4a2a2: 66fdee62 740c je PresentationCore_ni!`string'+0x4a2b0 (66fdee70) 66fdee64 8bc8 mov ecx,eax 66fdee66 8b01 mov eax,dword ptr [ecx] 66fdee68 ff90d8030000 call dword ptr [eax+3D8h] 66fdee6e 8bf0 mov esi,eax 66fdee70 8bd7 mov edx,edi 66fdee72 b998670467 mov ecx,offset PresentationCore_ni!`string'+0xb1bd8 (67046798) 66fdee77 e82c7afaff call PresentationCore_ni!?System.Windows.Media.Media3D.Viewport3DVisual.PrecomputeContent@@200001+0×3c (66f868a8)

The call structure seems to be valid when we check the next return address from the stack trace (67578500):

0:000> ub 67578500 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784e7): 675784e7 e8f4a2a0ff call PresentationCore_ni!?System.Windows.Media.Media3D.ScaleTransform3D.UpdateResource@@2002011280M802+0x108 (66f827e0) PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784ec): 675784ec eb05 jmp PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f3) (675784f3) PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784ee): 675784ee b801000000 mov eax,1 PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f3): 675784f3 85c0 test eax,eax PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f5): 675784f5 74b1 je PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784a8) (675784a8) PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f7): 675784f7 8bcb mov ecx,ebx PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784f9): 675784f9 33d2 xor edx,edx PresentationCore_ni!`string' <PERF> (PresentationCore_ni+0x7784fb): 675784fb e84069a6ff call PresentationCore_ni!`string’+0×4a280 (66fdee40)

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

Posted in .NET Debugging, Crash Dump Analysis, Crash Dump Patterns | No Comments »

Crash Dump Analysis Patterns (Part 219)

Saturday, February 7th, 2015

To complement Module patterns sub-catalogue we introduce Origin Module pattern. This is a module that may have originated the problem behavior. For example, when we look at a stack trace we may skip Top Modules due to our knowledge of the product, for example, if they are not known as Problem Modules or known as Well-Tested Modules. In case of Truncated Stack Traces we may designate bottom modules as possible problem origins. For example, for Reference Leak pattern example we may consider checking reference counting for selected modules such as ModuleA and ModuleB:

ad377ae8 +1 Dflt nt! ?? ::FNODOBFM::`string'+18f1d nt!ObpCallPreOperationCallbacks+4e nt!ObpPreInterceptHandleCreate+af nt! ?? ::NNGAKEGL::`string'+2c31f nt!ObOpenObjectByPointerWithTag+109 nt!PsOpenProcess+1a2 nt!NtOpenProcess+23 nt!KiSystemServiceCopyEnd+13 nt!KiServiceLinkage+0 ModuleA+dca63 ModuleA+b5bc ModuleA+c9c2e ModuleA+bae56 ModuleA+b938d ModuleA+c0ec6 ModuleA+afce7

ad377aeb -1 Dflt nt! ?? ::FNODOBFM::`string'+4886e nt!ObpCallPreOperationCallbacks+277 nt!ObpPreInterceptHandleCreate+af nt! ?? ::NNGAKEGL::`string'+2c31f nt!ObOpenObjectByPointerWithTag+109 nt!PsOpenProcess+1a2 nt!NtOpenProcess+23 nt!KiSystemServiceCopyEnd+13 nt!KiServiceLinkage+0 ModuleA+dca63 ModuleA+b5bc ModuleA+c9c2e ModuleA+bae56 ModuleA+b938d ModuleA+c0ec6 ModuleA+afce7

ad377af7 +1 Dflt nt! ?? ::NNGAKEGL::`string'+1fb41 nt!ObReferenceObjectByHandle+25 ModuleA+dcade ModuleA+b5bc ModuleA+c9c2e ModuleA+bae56 ModuleA+b938d ModuleA+c0ec6 ModuleA+afce7 ModuleA+87ca ModuleA+834a ModuleA+a522c ModuleA+a51b6 ModuleA+a4787 ModuleB+19c0c ModuleB+19b28

ad377afa -1 Dflt nt! ?? ::FNODOBFM::`string'+4886e ModuleA+dcbbe ModuleA+b5bc ModuleA+c9c2e ModuleA+bae56 ModuleA+b938d ModuleA+c0ec6 ModuleA+afce7 ModuleA+87ca ModuleA+834a ModuleA+a522c ModuleA+a51b6 ModuleA+a4787 ModuleB+19c0c ModuleB+19b28 ModuleB+b652

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging | 3 Comments »

Trace Analysis Patterns (Part 100)

Saturday, January 31st, 2015

Sometimes we need memory reference information not available in software traces and logs, for example, to see pointer dereferences, to follow pointers and linked structures. In such cases memory dumps saved during logging sessions may help. In case of process memory dumps we can even have several Step Dumps. Complete and kernel memory dumps may be forced after saving a log file. We call such pattern Adjoint Space:

Then we can analyze logs and memory dumps together, for example, to follow pointer data further in memory space:

There is also a reverse situation when we use logs to see past data changes before memory snapshot time (Paratext memory analysis pattern):

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

Posted in CDF Analysis Tips and Tricks, Core Dump Analysis, Crash Dump Analysis, Crash Dump Patterns, Debugging, Log Analysis, Software Trace Analysis, Software Trace Analysis Tips and Tricks, Software Trace Reading, Trace Analysis Patterns | No Comments »

Crash Dump Analysis Patterns (Part 218)

Wednesday, December 31st, 2014

Objects such as processes may be referenced internally in addition to using handles. If their reference counts are unbalanced we may have Reference Leak pattern. For example, we have an instance of thousands of Zombie Processes but we don’t see Handle Leaks from their parent processes if we analyze ParentCids:

0: kd> !process 0 0 [...] PROCESS fffffa801009a060 SessionId: 0 Cid: 2e270 Peb: 7fffffdb000 ParentCid: 032c DirBase: 12ba37000 ObjectTable: 00000000 HandleCount: 0. Image: conhost.exe

PROCESS fffffa8009b7e8e0 SessionId: 1 Cid: 2e0c8 Peb: 7fffffd9000 ParentCid: 10a0 DirBase: 21653e000 ObjectTable: 00000000 HandleCount: 0. Image: taskmgr.exe

PROCESS fffffa8009e7a450 SessionId: 0 Cid: 2e088 Peb: 7efdf000 ParentCid: 0478 DirBase: 107f02000 ObjectTable: 00000000 HandleCount: 0. Image: AppA.exe

PROCESS fffffa8009e794b0 SessionId: 0 Cid: 2e394 Peb: 7fffffd3000 ParentCid: 032c DirBase: 210ffc000 ObjectTable: 00000000 HandleCount: 0. Image: conhost.exe

PROCESS fffffa8009ed4060 SessionId: 0 Cid: 2dee4 Peb: 7efdf000 ParentCid: 0478 DirBase: 11b7c7000 ObjectTable: 00000000 HandleCount: 0. Image: AppB.exe

PROCESS fffffa800a13bb30 SessionId: 0 Cid: 2e068 Peb: 7fffffd5000 ParentCid: 032c DirBase: 1bb8c1000 ObjectTable: 00000000 HandleCount: 0. Image: conhost.exe

PROCESS fffffa80096f26b0 SessionId: 0 Cid: 2e320 Peb: 7efdf000 ParentCid: 0478 DirBase: 6ad4c000 ObjectTable: 00000000 HandleCount: 0. Image: AppC.exe

PROCESS fffffa8009c44060 SessionId: 0 Cid: 2e300 Peb: 7fffffdd000 ParentCid: 032c DirBase: 10df06000 ObjectTable: 00000000 HandleCount: 0. Image: conhost.exe [...]

0: kd> !object fffffa800a13bb30 Object: fffffa800a13bb30 Type: (fffffa8006cecf30) Process ObjectHeader: fffffa800a13bb00 (new version) HandleCount: 0 PointerCount: 1

0: kd> !object fffffa8009b7e8e0 Object: fffffa8009b7e8e0 Type: (fffffa8006cecf30) Process ObjectHeader: fffffa8009b7e8b0 (new version) HandleCount: 0 PointerCount: 1

Such number of processes correlates with non-paged pool usage for process structures:

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

NonPaged Paged Tag Allocs Frees Diff Used Allocs Frees Diff Used

Proc 55488 60 55428 80328320 0 0 0 0 Process objects , Binary: nt!ps File 51733526 51708737 24789 7150416 0 0 0 0 File objects […]

Here we recommend enabling object reference tracing either using gflags.exe or directly modifying registry:

Key: HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\kernel Value: ObTracePoolTags Type: REG_SZ Data: Proc

Note: after troubleshooting or debugging please disable tracing because it consumes pool (another variant of Instrumentation Side Effect pattern and may lead to similar Insufficient Memory pattern for stack trace database):

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

NonPaged Paged Tag Allocs Frees Diff Used Allocs Frees Diff Used

ObRt 5688634 5676109 12525 4817288240 0 0 0 0 object reference stack tracing , Binary: nt!ob Proc 22120 101 22019 25961168 0 0 0 0 Process objects , Binary: nt!ps […]

After enabling tracing we collect a complete memory dump (in case of postmortem debugging) to analyze another variant of Stack Trace pattern using !obtrace WinDbg command:

0: kd> !obtrace fffffa800af9e220 Object: fffffa800af9e220 Image: AppD.exe Sequence (+/-) Tag Stack -------- ----- ---- --------------------------------------------------- ad377858 +1 Dflt nt! ?? ::NNGAKEGL::`string'+21577 nt!PspAllocateProcess+185 nt!NtCreateUserProcess+4a3 nt!KiSystemServiceCopyEnd+13

ad37787d +1 Dflt nt! ?? ::FNODOBFM::`string'+18f1d nt!NtCreateUserProcess+569 nt!KiSystemServiceCopyEnd+13

ad377882 +1 Dflt nt! ?? ::NNGAKEGL::`string'+1f9d8 nt!NtProtectVirtualMemory+119 nt!KiSystemServiceCopyEnd+13 nt!KiServiceLinkage+0 nt!RtlCreateUserStack+1e4 nt!PspAllocateThread+299 nt!NtCreateUserProcess+65d nt!KiSystemServiceCopyEnd+13

ad377884 -1 Dflt nt! ?? ::FNODOBFM::`string'+4886e nt!NtProtectVirtualMemory+161 nt!KiSystemServiceCopyEnd+13 nt!KiServiceLinkage+0 nt!RtlCreateUserStack+1e4 [...]

Analysis of such traces may be complicated due to Truncated Stack Traces. We plan to show one counting trick in the next pattern.

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

Posted in Complete Memory Dump Analysis, Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 217)

Saturday, November 29th, 2014

Exception Module pattern is an obvious pattern we add for pattern language completeness. It is a module or component where the actual exception happened, for example, ModuleA from this Exception Stack Trace:

9 Id: 1df4.a08 Suspend: -1 Teb: 7fff4000 Unfrozen ChildEBP RetAddr 1022f5a8 7c90df4a ntdll!KiFastSystemCallRet 1022f5ac 7c8648a2 ntdll!ZwWaitForMultipleObjects+0xc 1022f900 7c83ab50 kernel32!UnhandledExceptionFilter+0×8b9 1022f908 7c839b39 kernel32!BaseThreadStart+0×4d 1022f930 7c9032a8 kernel32!_except_handler3+0×61 1022f954 7c90327a ntdll!ExecuteHandler2+0×26 1022fa04 7c90e48a ntdll!ExecuteHandler+0×24 1022fa04 7c812afb ntdll!KiUserExceptionDispatcher+0xe 1022fd5c 0b82e680 kernel32!RaiseException+0×53 WARNING: Stack unwind information not available. Following frames may be wrong. 1022fd94 0b82d2f2 ModuleA+0×21e640 1022fde8 7753004f ModuleA+0×21d4f2 1022fdfc 7753032f ole32!CClassCache::CDllPathEntry::CanUnload_rl+0×3b 1022ff3c 7753028b ole32!CClassCache::FreeUnused+0×70 1022ff4c 775300b5 ole32!CoFreeUnusedLibrariesEx+0×36 1022ff58 77596af5 ole32!CoFreeUnusedLibraries+0×9 1022ff6c 77566ff9 ole32!CDllHost::MTAWorkerLoop+0×25 1022ff8c 7752687c ole32!CDllHost::WorkerThread+0xc1 1022ff94 774fe3ee ole32!DLLHostThreadEntry+0xd 1022ffa8 774fe456 ole32!CRpcThread::WorkerLoop+0×1e 1022ffb4 7c80b729 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×1b 1022ffec 00000000 kernel32!BaseThreadStart+0×37

Because we have a software exception we can use backwards disassembly (ub WinDbg command) to check stack trace correctness in case of stack unwind warnings (like in Coincidental Symbolic Information pattern). Here’s another example, for recent MS Paint crash we observed, with msvcrt exception module. However, if we skip it as a Well-Tested Module, the next exception module candidate is mspaint.

0:000> kc Call Site ntdll!NtWaitForMultipleObjects KERNELBASE!WaitForMultipleObjectsEx kernel32!WaitForMultipleObjectsExImplementation kernel32!WerpReportFaultInternal kernel32!WerpReportFault kernel32!BasepReportFault kernel32!UnhandledExceptionFilter ntdll! ?? ::FNODOBFM::`string' ntdll!_C_specific_handler ntdll!RtlpExecuteHandlerForException ntdll!RtlDispatchException ntdll!KiUserExceptionDispatch msvcrt!memcpy mspaint!CImgWnd::CmdCrop mspaint!CPBView::OnImageCrop mfc42u!_AfxDispatchCmdMsg mfc42u!CCmdTarget::OnCmdMsg mfc42u!CView::OnCmdMsg mspaint!CPBView::OnCmdMsg mfc42u!CFrameWnd::OnCmdMsg mspaint!CGenericCommandSite::XGenericCommandSiteCommandHandler::Execute UIRibbon!CControlUser::_ExecuteOnHandler UIRibbon!CGenericControlUser::SetValueImpl UIRibbon!CGenericDataSource::SetValue UIRibbon!OfficeSpace::DataSource::SetValue UIRibbon!OfficeSpace::FSControl::SetValue UIRibbon!NetUI::DeferCycle::ProcessDataBindingPropertyChangeRecords UIRibbon!NetUI::DeferCycle::HrAddDataBindingPropertyChangeRecord UIRibbon!NetUI::Binding::SetDataSourceValue UIRibbon!NetUI::Bindings::OnBindingPropertyChanged UIRibbon!NetUI::Node::OnPropertyChanged UIRibbon!FlexUI::Concept::OnPropertyChanged UIRibbon!NetUI::Node::FExecuteCommand UIRibbon!FlexUI::ExecuteAction::OnCommand UIRibbon!NetUI::Node::FExecuteCommand UIRibbon!NetUI::SimpleButton::OnEvent UIRibbon!NetUI::Element::_DisplayNodeCallback UIRibbon!GPCB::xwInvokeDirect UIRibbon!GPCB::xwInvokeFull UIRibbon!DUserSendEvent UIRibbon!NetUI::Element::FireEvent UIRibbon!NetUI::_FireClickEvent UIRibbon!NetUI::SimpleButton::OnInput UIRibbon!NetUI::Element::_DisplayNodeCallback UIRibbon!GPCB::xwInvokeDirect UIRibbon!GPCB::xwInvokeFull UIRibbon!BaseMsgQ::xwProcessNL UIRibbon!DelayedMsgQ::xwProcessDelayedNL UIRibbon!ContextLock::~ContextLock UIRibbon!HWndContainer::xdHandleMessage UIRibbon!ExtraInfoWndProc user32!UserCallWinProcCheckWow user32!DispatchMessageWorker mfc42u!CWinThread::PumpMessage mfc42u!CWinThread::Run mfc42u!AfxWinMain mspaint!LDunscale kernel32!BaseThreadInitThunk ntdll!RtlUserThreadStart

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Debugging | No Comments »

Crash Dump Analysis Patterns (Part 216)

Wednesday, November 19th, 2014

Sometimes what looks like a memory leak when we install the new product version is not really a leak. With the previous version we had 400 MB typical memory usage but suddenly we get twice as more. We shouldn’t panic but collect a process memory dump to calmly inspect it offline. We may see Dry Weight increase: the size of all module images. For some products the new release may mean complete redesign with a new more powerful framework or incorporation of the significant number of new 3rd-party components (Module Variety). Additional sign against the memory leak hypothesis is simultaneous memory usage increase for many product processes. Although, this may be some shared module with leaking code. For example, in the example below 50% of all committed memory was image memory:

0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal [...] Image 1806 0`19031000 ( 402.535 Mb) 4.29% 0.00% Heap 72 0`02865000 ( 40.395 Mb) 0.44% 0.00% […]

--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal [...] MEM_IMAGE 2281 0`19AA8000 ( 413.000 Mb) 4.40% 0.00% […]

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal [...] MEM_COMMIT 2477 0`326e8000 ( 806.906 Mb) 8.76% 0.00% […]

WinDbg lmt command shows almost 50 new .NET components.

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

Posted in .NET Debugging, Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 215)

Sunday, November 16th, 2014

Sometimes Wait Chains such as involving critical sections may have a Missing Thread endpoint. But in some cases we might see a Ghost Thread whose TID was reused by subsequent thread creation in a different process. For example, critical section structure may refer to such TID as in the example below.

// Critical section from LSASS process

THREAD fffffa803431cb50 Cid 03e8.2718 Teb: 000007fffff80000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable fffffa80330e0500 SynchronizationEvent Impersonation token: fffff8a00b807060 (Level Impersonation) Owning Process fffffa8032354c40 Image: lsass.exe Attached Process N/A Image: N/A Wait Start TickCount 107175 Ticks: 19677 (0:00:05:06.963) Context Switch Count 2303 IdealProcessor: 1 UserTime 00:00:00.218 KernelTime 00:00:00.109 Win32 Start Address ntdll!TppWorkerThread (0×0000000076e1f2e0) Stack Init fffff88008e5fdb0 Current fffff88008e5f900 Base fffff88008e60000 Limit fffff88008e5a000 Call 0 Priority 10 BasePriority 10 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5 Kernel stack not resident. Child-SP RetAddr Call Site fffff880`08e5f940 fffff800`01c7cf72 nt!KiSwapContext+0×7a fffff880`08e5fa80 fffff800`01c8e39f nt!KiCommitThreadWait+0×1d2 fffff880`08e5fb10 fffff800`01f7fe3e nt!KeWaitForSingleObject+0×19f fffff880`08e5fbb0 fffff800`01c867d3 nt!NtWaitForSingleObject+0xde fffff880`08e5fc20 00000000`76e5067a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`08e5fc20) 00000000`0427cca8 00000000`76e4d808 ntdll!NtWaitForSingleObject+0xa 00000000`0427ccb0 00000000`76e4d6fb ntdll!RtlpWaitOnCriticalSection+0xe8 00000000`0427cd60 000007fe`f46a4afe ntdll!RtlEnterCriticalSection+0xd1 […]

1: kd> .process /r /p fffffa8032354c40 Implicit process is now fffffa80`32353b30 Loading User Symbols

1: kd> !cs -l -o -s ----------------------------------------- DebugInfo = 0x0000000003475220 Critical section = 0x0000000003377740 (+0x3377740) LOCKED LockCount = 0×10 WaiterWoken = No OwningThread = 0×00000000000004e4 RecursionCount = 0×0 LockSemaphore = 0×0 SpinCount = 0×0000000000000000 OwningThread = .thread fffffa80344e4c00 […]

// The "owner" thread is from winlogon.exe

1: kd> !thread fffffa80344e4c00 3f THREAD fffffa80344e4c00 Cid 21d0.14e4 Teb: 000007fffffae000 Win32Thread: fffff900c0998c20 WAIT: (WrUserRequest) UserMode Non-Alertable fffffa80355817d0 SynchronizationEvent Not impersonating DeviceMap fffff8a0000088f0 Owning Process fffffa8034ff77c0 Image: winlogon.exe […]

A PML (Process Monitor) log was recorded before the complete memory dump was forced, and it clearly shows Glued Activity trace analysis pattern. The thread was owned by LSASS but then exited and its TID was subsequently reused by 2 other processes.

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

Posted in Complete Memory Dump Analysis, Crash Dump Analysis, Crash Dump Patterns, Software Trace Analysis, Trace Analysis Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 61b)

Saturday, November 15th, 2014

We recently encountered Invalid Handle pattern in the context of .NET program execution. We decided to model it and wrote a small C# program:

namespace SafeHandle
{
    class Program
    {
        static void Main(string[] args)
        {
            SafeFileHandle hFile =
                 new SafeFileHandle(new IntPtr(0xDEAD), true);
            Console.WriteLine("About to close");
            Console.ReadKey();
        }
    }
}

Of course, when we execute it nothing happens. Invalid handles are ignored by default. However, to change the behavior we enabled “Enable close exception” in glags.exe:

And if we run it we get this Managed Stack Trace:

We could have detected invalid handle if we enabled Application Verifier but then we wouldn’t have Managed Code Exception.

So we load a crash dump (saved because we enabled LocalDumps) and load SOS extension:

0:002> lmv m clr start end module name 000007fe`ed880000 000007fe`ee1eb000 clr (pdb symbols) Loaded symbol image file: clr.dll Image path: C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll [...]

0:002> .load C:\Windows\Microsoft.NET\Framework64\v4.0.30319\sos

0:002> !pe Exception object: 0000000002ab5fe8 Exception type: System.Runtime.InteropServices.SEHException Message: External component has thrown an exception. InnerException: StackTrace (generated): SP IP Function 000000001B40EDD0 0000000000000000 mscorlib_ni!Microsoft.Win32.Win32Native.CloseHandle(IntPtr)+0×1 000000001B40F2F0 0000000000000000 mscorlib_ni!System.Runtime.InteropServices.SafeHandle.InternalFinalize()+0×1 000000001B40F2F0 000007FEEC62F7A6 mscorlib_ni!System.Runtime.InteropServices.SafeHandle.Finalize()+0×26

StackTraceString: HResult: 80004005

Our unmanaged CLR Thread Exception Stack Trace is quite simple:

0:002> k Child-SP RetAddr Call Site 00000000`1b40d6e8 000007fe`fd651430 ntdll!NtWaitForMultipleObjects+0xa 00000000`1b40d6f0 00000000`77621723 KERNELBASE!WaitForMultipleObjectsEx+0xe8 00000000`1b40d7f0 00000000`7769b5e5 kernel32!WaitForMultipleObjectsExImplementation+0xb3 00000000`1b40d880 00000000`7769b767 kernel32!WerpReportFaultInternal+0x215 00000000`1b40d920 00000000`7769b7bf kernel32!WerpReportFault+0x77 00000000`1b40d950 00000000`7769b9dc kernel32!BasepReportFault+0x1f 00000000`1b40d980 00000000`778b3398 kernel32!UnhandledExceptionFilter+0x1fc 00000000`1b40da60 00000000`778385c8 ntdll! ?? ::FNODOBFM::`string'+0x2365 00000000`1b40da90 00000000`77849d2d ntdll!_C_specific_handler+0x8c 00000000`1b40db00 00000000`778391cf ntdll!RtlpExecuteHandlerForException+0xd 00000000`1b40db30 00000000`778397c8 ntdll!RtlDispatchException+0x45a 00000000`1b40e210 00000000`778712c7 ntdll!RtlRaiseException+0x22f 00000000`1b40ebc0 000007fe`fd651873 ntdll!KiRaiseUserExceptionDispatcher+0×3a 00000000`1b40ec90 00000000`77621991 KERNELBASE!CloseHandle+0×13 00000000`1b40ecc0 000007fe`ec720418 kernel32!CloseHandleImplementation+0×3d 00000000`1b40edd0 000007fe`ed8e9e03 mscorlib_ni+0×580418 00000000`1b40eea0 000007fe`ed8e9e7e clr!CallDescrWorkerInternal+0×83 00000000`1b40eee0 000007fe`ed8ec860 clr!CallDescrWorkerWithHandler+0×4a 00000000`1b40ef20 000007fe`ed8f1a1d clr!DispatchCallSimple+0×85 00000000`1b40efb0 000007fe`ed8f19ac clr!SafeHandle::RunReleaseMethod+0×69 00000000`1b40f050 000007fe`ed8f180a clr!SafeHandle::Release+0×122 00000000`1b40f120 000007fe`eda4863e clr!SafeHandle::Dispose+0×36 00000000`1b40f190 000007fe`ec62f7a6 clr!SafeHandle::Finalize+0xa2 00000000`1b40f2f0 000007fe`ed8e9d56 mscorlib_ni+0×48f7a6 00000000`1b40f330 000007fe`eda83c4e clr!FastCallFinalizeWorker+0×6 00000000`1b40f360 000007fe`eda83bc3 clr!MethodDesc::RequiresFullSlotNumber+0×72 00000000`1b40f3a0 000007fe`eda83b0f clr!MethodTable::CallFinalizer+0xa3 00000000`1b40f3e0 000007fe`ed9fee46 clr!SVR::CallFinalizer+0×5f 00000000`1b40f420 000007fe`ed9aac5b clr!SVR::CallFinalizer+0×102 00000000`1b40f4e0 000007fe`ed8f458c clr!WKS::GCHeap::IsPromoted+0xee 00000000`1b40f520 000007fe`ed8f451a clr!Frame::Pop+0×50 00000000`1b40f560 000007fe`ed8f4491 clr!COMCustomAttribute::PopSecurityContextFrame+0×192 00000000`1b40f660 000007fe`ed9d1bfe clr!COMCustomAttribute::PopSecurityContextFrame+0xbd 00000000`1b40f6f0 000007fe`ed9d1e59 clr!ManagedThreadBase_NoADTransition+0×3f 00000000`1b40f750 000007fe`ed9533de clr!WKS::GCHeap::FinalizerThreadStart+0×193 00000000`1b40f790 00000000`776159ed clr!Thread::intermediateThreadProc+0×7d 00000000`1b40f850 00000000`7784c541 kernel32!BaseThreadInitThunk+0xd 00000000`1b40f880 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

We see that exception processing happened during object finalization. We can infer the value of the handle (may be Small Value) via disassembly if this is possible:

0:002> kn # Child-SP RetAddr Call Site 00 00000000`1b40d6e8 000007fe`fd651430 ntdll!NtWaitForMultipleObjects+0xa 01 00000000`1b40d6f0 00000000`77621723 KERNELBASE!WaitForMultipleObjectsEx+0xe8 02 00000000`1b40d7f0 00000000`7769b5e5 kernel32!WaitForMultipleObjectsExImplementation+0xb3 03 00000000`1b40d880 00000000`7769b767 kernel32!WerpReportFaultInternal+0x215 04 00000000`1b40d920 00000000`7769b7bf kernel32!WerpReportFault+0x77 05 00000000`1b40d950 00000000`7769b9dc kernel32!BasepReportFault+0x1f 06 00000000`1b40d980 00000000`778b3398 kernel32!UnhandledExceptionFilter+0x1fc 07 00000000`1b40da60 00000000`778385c8 ntdll! ?? ::FNODOBFM::`string'+0x2365 08 00000000`1b40da90 00000000`77849d2d ntdll!_C_specific_handler+0x8c 09 00000000`1b40db00 00000000`778391cf ntdll!RtlpExecuteHandlerForException+0xd 0a 00000000`1b40db30 00000000`778397c8 ntdll!RtlDispatchException+0x45a 0b 00000000`1b40e210 00000000`778712c7 ntdll!RtlRaiseException+0x22f 0c 00000000`1b40ebc0 000007fe`fd651873 ntdll!KiRaiseUserExceptionDispatcher+0x3a 0d 00000000`1b40ec90 00000000`77621991 KERNELBASE!CloseHandle+0×13 0e 00000000`1b40ecc0 000007fe`ec720418 kernel32!CloseHandleImplementation+0×3d 0f 00000000`1b40edd0 000007fe`ed8e9e03 mscorlib_ni+0×580418 10 00000000`1b40eea0 000007fe`ed8e9e7e clr!CallDescrWorkerInternal+0×83 11 00000000`1b40eee0 000007fe`ed8ec860 clr!CallDescrWorkerWithHandler+0×4a 12 00000000`1b40ef20 000007fe`ed8f1a1d clr!DispatchCallSimple+0×85 13 00000000`1b40efb0 000007fe`ed8f19ac clr!SafeHandle::RunReleaseMethod+0×69 14 00000000`1b40f050 000007fe`ed8f180a clr!SafeHandle::Release+0×122 15 00000000`1b40f120 000007fe`eda4863e clr!SafeHandle::Dispose+0×36 16 00000000`1b40f190 000007fe`ec62f7a6 clr!SafeHandle::Finalize+0xa2 17 00000000`1b40f2f0 000007fe`ed8e9d56 mscorlib_ni+0×48f7a6 18 00000000`1b40f330 000007fe`eda83c4e clr!FastCallFinalizeWorker+0×6 19 00000000`1b40f360 000007fe`eda83bc3 clr!MethodDesc::RequiresFullSlotNumber+0×72 1a 00000000`1b40f3a0 000007fe`eda83b0f clr!MethodTable::CallFinalizer+0xa3 1b 00000000`1b40f3e0 000007fe`ed9fee46 clr!SVR::CallFinalizer+0×5f 1c 00000000`1b40f420 000007fe`ed9aac5b clr!SVR::CallFinalizer+0×102 1d 00000000`1b40f4e0 000007fe`ed8f458c clr!WKS::GCHeap::IsPromoted+0xee 1e 00000000`1b40f520 000007fe`ed8f451a clr!Frame::Pop+0×50 1f 00000000`1b40f560 000007fe`ed8f4491 clr!COMCustomAttribute::PopSecurityContextFrame+0×192 20 00000000`1b40f660 000007fe`ed9d1bfe clr!COMCustomAttribute::PopSecurityContextFrame+0xbd 21 00000000`1b40f6f0 000007fe`ed9d1e59 clr!ManagedThreadBase_NoADTransition+0×3f 22 00000000`1b40f750 000007fe`ed9533de clr!WKS::GCHeap::FinalizerThreadStart+0×193 23 00000000`1b40f790 00000000`776159ed clr!Thread::intermediateThreadProc+0×7d 24 00000000`1b40f850 00000000`7784c541 kernel32!BaseThreadInitThunk+0xd 25 00000000`1b40f880 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:002> .frame /c d 0d 00000000`1b40ec90 00000000`77621991 KERNELBASE!CloseHandle+0x13 rax=00000000c0000001 rbx=000000000000dead rcx=00000000009a0000 rdx=0000000000000001 rsi=000000001b40efd0 rdi=000000001b40eff8 rip=000007fefd651873 rsp=000000001b40ec90 rbp=000000001b40edf0 r8=000000001b40ce08 r9=000000001b40cf70 r10=0000000000000000 r11=0000000000000246 r12=0000000000000001 r13=0000000040000000 r14=000000001b40ef40 r15=0000000000000000 iopl=0 nv up ei pl zr na po nc cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246 KERNELBASE!CloseHandle+0×13: 000007fe`fd651873 85c0 test eax,eax

0:002> ub 00000000`77621991 kernel32!CloseHandleImplementation+0×1e: 00000000`7762196e 83f9f4 cmp ecx,0FFFFFFF4h 00000000`77621971 0f83952e0100 jae kernel32!TlsGetValue+0×3ef0 (00000000`7763480c) 00000000`77621977 488bc3 mov rax,rbx 00000000`7762197a 2503000010 and eax,10000003h 00000000`7762197f 4883f803 cmp rax,3 00000000`77621983 0f847f8dfeff je kernel32!CloseHandleImplementation+0×56 (00000000`7760a708) 00000000`77621989 488bcb mov rcx,rbx 00000000`7762198c e81f000000 call kernel32!CloseHandle (00000000`776219b0)

Here we also check the value from the managed stack trace or from Execution Residue:

0:002> !CLRStack -a OS Thread Id: 0x1390 (2) Child SP IP Call Site 000000001b40edf8 000000007787186a [InlinedCallFrame: 000000001b40edf8] Microsoft.Win32.Win32Native.CloseHandle(IntPtr) 000000001b40edf8 000007feec720418 [InlinedCallFrame: 000000001b40edf8] Microsoft.Win32.Win32Native.CloseHandle(IntPtr) 000000001b40edd0 000007feec720418 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr) PARAMETERS: <no data>

000000001b40eff8 000007feed8e9e03 [GCFrame: 000000001b40eff8] 000000001b40f148 000007feed8e9e03 [GCFrame: 000000001b40f148] 000000001b40f1f8 000007feed8e9e03 [HelperMethodFrame_1OBJ: 000000001b40f1f8] System.Runtime.InteropServices.SafeHandle.InternalFinalize() 000000001b40f2f0 000007feec62f7a6 System.Runtime.InteropServices.SafeHandle.Finalize() PARAMETERS: this (0x000000001b40f330) = 0×0000000002ab2d78

000000001b40f6a8 000007feed8e9d56 [DebuggerU2MCatchHandlerFrame: 000000001b40f6a8]

0:002> !dso OS Thread Id: 0x1390 (2) RSP/REG Object Name 000000001B40EEA0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40EFD0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F038 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F050 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F090 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F120 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F190 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F1B8 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F240 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F2F8 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F330 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F360 0000000002ab5e10 System.Threading.Thread 000000001B40F390 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F3E0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F3F0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle 000000001B40F430 0000000002ab58a8 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle 000000001B40F4E0 0000000002ab2d78 Microsoft.Win32.SafeHandles.SafeFileHandle

0:002> !do 0000000002ab2d78 Name: Microsoft.Win32.SafeHandles.SafeFileHandle MethodTable: 000007feec88a260 EEClass: 000007feec34d340 Size: 32(0x20) bytes File: C:\windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll Fields: MT Field Offset Type VT Attr Value Name 000007feec88a338 400060d 8 System.IntPtr 1 instance dead handle 000007feec8892b8 400060e 10 System.Int32 1 instance 3 _state 000007feec887de0 400060f 14 System.Boolean 1 instance 1 _ownsHandle 000007feec887de0 4000610 15 System.Boolean 1 instance 1 _fullyInitialized

Please note that we don’t have global application flags:

0:002> !gflag Current NtGlobalFlag contents: 0x00000000

Here is the exception stack trace from a different crash dump when we enable Application Verifier:

0:002> !gflag Current NtGlobalFlag contents: 0x02000100 vrf - Enable application verifier hpa - Place heap allocations at ends of pages

0:002> k Child-SP RetAddr Call Site 00000000`24bac4a8 00000000`77cd3072 ntdll!NtWaitForSingleObject+0xa 00000000`24bac4b0 00000000`77cd32b5 ntdll!RtlReportExceptionEx+0x1d2 00000000`24bac5a0 000007fe`fa2c26fb ntdll!RtlReportException+0xb5 00000000`24bac620 00000000`77c2a5db verifier!AVrfpVectoredExceptionHandler+0x26b 00000000`24bac6b0 00000000`77c28e62 ntdll!RtlpCallVectoredHandlers+0xa8 00000000`24bac720 00000000`77c61248 ntdll!RtlDispatchException+0x22 00000000`24bace00 000007fe`fa2bae03 ntdll!KiUserExceptionDispatch+0x2e 00000000`24bad500 000007fe`fa2c268a verifier!VerifierStopMessageEx+0x6fb 00000000`24bad850 00000000`77c2a5db verifier!AVrfpVectoredExceptionHandler+0x1fa 00000000`24bad8e0 00000000`77c28e62 ntdll!RtlpCallVectoredHandlers+0xa8 00000000`24bad950 00000000`77c297c8 ntdll!RtlDispatchException+0x22 00000000`24bae030 00000000`77c612c7 ntdll!RtlRaiseException+0x22f 00000000`24bae9e0 000007fe`fa2d2386 ntdll!KiRaiseUserExceptionDispatcher+0x3a 00000000`24baeab0 000007fe`fdbd1873 verifier!AVrfpNtClose+0xbe 00000000`24baeae0 000007fe`fa2d4031 KERNELBASE!CloseHandle+0x13 00000000`24baeb10 000007fe`fa2d40cb verifier!AVrfpCloseHandleCommon+0x95 00000000`24baeb40 00000000`77a11991 verifier!AVrfpKernelbaseCloseHandle+0x23 00000000`24baeb80 000007fe`fa2d4031 kernel32!CloseHandleImplementation+0x3d 00000000`24baec90 000007fe`fa2d409c verifier!AVrfpCloseHandleCommon+0x95 *** WARNING: Unable to verify checksum for mscorlib.ni.dll 00000000`24baecc0 000007fe`e6a40418 verifier!AVrfpKernel32CloseHandle+0x2c 00000000`24baed00 000007fe`ec0e9e03 mscorlib_ni+0x580418 00000000`24baedd0 000007fe`ec0e9e7e clr!CallDescrWorkerInternal+0x83 00000000`24baee10 000007fe`ec0ec860 clr!CallDescrWorkerWithHandler+0x4a 00000000`24baee50 000007fe`ec0f1a1d clr!DispatchCallSimple+0x85 00000000`24baeee0 000007fe`ec0f19ac clr!SafeHandle::RunReleaseMethod+0x69 00000000`24baef80 000007fe`ec0f180a clr!SafeHandle::Release+0x122 00000000`24baf050 000007fe`ec24863e clr!SafeHandle::Dispose+0x36 00000000`24baf0c0 000007fe`e694f7a6 clr!SafeHandle::Finalize+0xa2 00000000`24baf220 000007fe`ec0e9d56 mscorlib_ni+0x48f7a6 00000000`24baf260 000007fe`ec283c4e clr!FastCallFinalizeWorker+0x6 00000000`24baf290 000007fe`ec283bc3 clr!MethodDesc::RequiresFullSlotNumber+0x72 00000000`24baf2d0 000007fe`ec283b0f clr!MethodTable::CallFinalizer+0xa3 00000000`24baf310 000007fe`ec1fee46 clr!SVR::CallFinalizer+0x5f 00000000`24baf350 000007fe`ec1aac5b clr!SVR::CallFinalizer+0x102 00000000`24baf410 000007fe`ec0f458c clr!WKS::GCHeap::IsPromoted+0xee 00000000`24baf450 000007fe`ec0f451a clr!Frame::Pop+0x50 00000000`24baf490 000007fe`ec0f4491 clr!COMCustomAttribute::PopSecurityContextFrame+0x192 00000000`24baf590 000007fe`ec1d1bfe clr!COMCustomAttribute::PopSecurityContextFrame+0xbd 00000000`24baf620 000007fe`ec1d1e59 clr!ManagedThreadBase_NoADTransition+0x3f 00000000`24baf680 000007fe`ec1533de clr!WKS::GCHeap::FinalizerThreadStart+0x193 00000000`24baf6c0 000007fe`fa2d4b87 clr!Thread::intermediateThreadProc+0x7d 00000000`24baf780 00000000`77a059ed verifier!AVrfpStandardThreadFunction+0x2b 00000000`24baf7c0 00000000`77c3c541 kernel32!BaseThreadInitThunk+0xd 00000000`24baf7f0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

0:002> !pe There is no current managed exception on this thread

0:002> !CLRStack OS Thread Id: 0x51e4 (2) Child SP IP Call Site 0000000024baed28 0000000077c612fa [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr) 0000000024baed28 000007fee6a40418 [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr) 0000000024baed00 000007fee6a40418 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr) 0000000024baef28 000007feec0e9e03 [GCFrame: 0000000024baef28] 0000000024baf078 000007feec0e9e03 [GCFrame: 0000000024baf078] 0000000024baf128 000007feec0e9e03 [HelperMethodFrame_1OBJ: 0000000024baf128] System.Runtime.InteropServices.SafeHandle.InternalFinalize() 0000000024baf220 000007fee694f7a6 System.Runtime.InteropServices.SafeHandle.Finalize() 0000000024baf5d8 000007feec0e9d56 [DebuggerU2MCatchHandlerFrame: 0000000024baf5d8]

0:002> !dso OS Thread Id: 0x51e4 (2) RSP/REG Object Name 0000000024BAEDD0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAEF00 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAEF68 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAEF80 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAEFC0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF050 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF0C0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF0E8 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF170 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF228 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF260 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF290 000000000c285e10 System.Threading.Thread 0000000024BAF2C0 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF310 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF320 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle 0000000024BAF360 000000000c2858a8 Microsoft.Win32.SafeHandles.SafeViewOfFileHandle 0000000024BAF410 000000000c282d78 Microsoft.Win32.SafeHandles.SafeFileHandle

0:002> !CLRStack -a OS Thread Id: 0x51e4 (2) Child SP IP Call Site 0000000024baed28 0000000077c612fa [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr) 0000000024baed28 000007fee6a40418 [InlinedCallFrame: 0000000024baed28] Microsoft.Win32.Win32Native.CloseHandle(IntPtr) 0000000024baed00 000007fee6a40418 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr) PARAMETERS: <no data>

0000000024baef28 000007feec0e9e03 [GCFrame: 0000000024baef28] 0000000024baf078 000007feec0e9e03 [GCFrame: 0000000024baf078] 0000000024baf128 000007feec0e9e03 [HelperMethodFrame_1OBJ: 0000000024baf128] System.Runtime.InteropServices.SafeHandle.InternalFinalize() 0000000024baf220 000007fee694f7a6 System.Runtime.InteropServices.SafeHandle.Finalize() PARAMETERS: this (0x0000000024baf260) = 0×000000000c282d78

0000000024baf5d8 000007feec0e9d56 [DebuggerU2MCatchHandlerFrame: 0000000024baf5d8]

0:002> !do 0x000000000c282d78 Name: Microsoft.Win32.SafeHandles.SafeFileHandle MethodTable: 000007fee6baa260 EEClass: 000007fee666d340 Size: 32(0x20) bytes File: C:\windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll Fields: MT Field Offset Type VT Attr Value Name 000007fee6baa338 400060d 8 System.IntPtr 1 instance dead handle 000007fee6ba92b8 400060e 10 System.Int32 1 instance 3 _state 000007fee6ba7de0 400060f 14 System.Boolean 1 instance 1 _ownsHandle 000007fee6ba7de0 4000610 15 System.Boolean 1 instance 1 _fullyInitialized

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

Posted in .NET Debugging, Crash Dump Analysis, Crash Dump Patterns, Debugging, Software Defect Construction, x64 Windows | 1 Comment »

Crash Dump Analysis Patterns (Part 20e)

Thursday, October 30th, 2014

The set of memory dumps that prompted to introduce Insufficient Memory pattern for stack trace database also prompted to include a variant of Memory Leak pattern related to regions of virtual memory address space. We created this simple modeling application:

int _tmain(int argc, _TCHAR* argv[])
{
	int i,j;

	for (i = 1; i < 1000; ++i)
	{
		for (j = 1; j < 1000; ++j)
		{
			VirtualAlloc(NULL, 0x10000, MEM_RESERVE,
                                     PAGE_EXECUTE_READWRITE);
		}
		getc(stdin);
	}
	return 0;
}

We allocated only reserved memory regions. Committing them would probably at some stage manifest Insufficient Memory patterns for committed memory and physical memory. So we took a few consecutive memory dumps and see the ever increasing number of regions allocated at greater and greater virtual addresses:

0:000> !address [...] * 0`04070000 0`04080000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04080000 0`04090000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04090000 0`040a0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`040a0000 0`040b0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`040b0000 0`040c0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`040c0000 0`040d0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`040d0000 0`040e0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`040e0000 0`040f0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`040f0000 0`04100000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04100000 0`04110000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04110000 0`04120000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04120000 0`04130000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04130000 0`04140000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`04140000 0`04260000 0`00120000 MEM_FREE PAGE_NOACCESS Free [...]

0:000> !address [...] * 0`2eec0000 0`2eed0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2eed0000 0`2eee0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2eee0000 0`2eef0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2eef0000 0`2ef00000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef00000 0`2ef10000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef10000 0`2ef20000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef20000 0`2ef30000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef30000 0`2ef40000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef40000 0`2ef50000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef50000 0`2ef60000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef60000 0`2ef70000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef70000 0`2ef80000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef80000 0`2ef90000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2ef90000 0`2efa0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2efa0000 0`2efb0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2efb0000 0`2efc0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2efc0000 0`2efd0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2efd0000 0`2efe0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2efe0000 0`2eff0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2eff0000 0`2f000000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2f000000 0`2f010000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`2f010000 0`2f170000 0`00160000 MEM_FREE PAGE_NOACCESS Free [...]

0:000> !address [...] * 0`697f0000 0`69800000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69800000 0`69810000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69810000 0`69820000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69820000 0`69830000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69830000 0`69840000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69840000 0`69850000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69850000 0`69860000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69860000 0`69870000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69870000 0`69880000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69880000 0`69890000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`69890000 0`698a0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`698a0000 0`699e0000 0`00140000 MEM_FREE PAGE_NOACCESS Free [...]

0:000> !address [...] * 0`c08c0000 0`c08d0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c08d0000 0`c08e0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c08e0000 0`c08f0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c08f0000 0`c0900000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c0900000 0`c0910000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c0910000 0`c0920000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c0920000 0`c0930000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 0`c0930000 0`c0960000 0`00030000 MEM_FREE PAGE_NOACCESS Free [...]

0:000> !address [...] * 1`3d6a0000 1`3d6b0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d6b0000 1`3d6c0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d6c0000 1`3d6d0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d6d0000 1`3d6e0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d6e0000 1`3d6f0000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d6f0000 1`3d700000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d700000 1`3d710000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d710000 1`3d720000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d720000 1`3d730000 0`00010000 MEM_PRIVATE MEM_RESERVE <unclassified> * 1`3d730000 1`3d7a0000 0`00070000 MEM_FREE PAGE_NOACCESS Free [...]

0:000> !address -summary

--- Usage Summary ---------------- RgnCount ———– Total Size ——– %ofBusy %ofTotal Free 15 7fe`c275e000 ( 7.995 Tb) 99.94% <unclassified> 80928 1`3d193000 ( 4.955 Gb) 99.86% 0.06% Image 28 0`0034b000 ( 3.293 Mb) 0.06% 0.00% Stack 6 0`00200000 ( 2.000 Mb) 0.04% 0.00% MemoryMappedFile 8 0`001af000 ( 1.684 Mb) 0.03% 0.00% TEB 2 0`00004000 ( 16.000 kb) 0.00% 0.00% PEB 1 0`00001000 ( 4.000 kb) 0.00% 0.00%

--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal MEM_PRIVATE 80936 1`3d397000 ( 4.957 Gb) 99.90% 0.06% MEM_IMAGE 29 0`0034c000 ( 3.297 Mb) 0.06% 0.00% MEM_MAPPED 8 0`001af000 ( 1.684 Mb) 0.03% 0.00%

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal MEM_FREE 15 7fe`c275e000 ( 7.995 Tb) 99.94% MEM_RESERVE 80926 1`3d438000 ( 4.957 Gb) 99.91% 0.06% MEM_COMMIT 47 0`0045a000 ( 4.352 Mb) 0.09% 0.00%

--- Protect Summary (for commit) - RgnCount ----------- Total Size -------- %ofBusy %ofTotal PAGE_EXECUTE_READ 4 0`001ef000 ( 1.934 Mb) 0.04% 0.00% PAGE_READONLY 19 0`001de000 ( 1.867 Mb) 0.04% 0.00% PAGE_READWRITE 17 0`00080000 ( 512.000 kb) 0.01% 0.00% PAGE_WRITECOPY 5 0`00008000 ( 32.000 kb) 0.00% 0.00% PAGE_READWRITE|PAGE_GUARD 2 0`00005000 ( 20.000 kb) 0.00% 0.00%

--- Largest Region by Usage ----------- Base Address -------- Region Size ---------- Free 1`3fac7000 7fd`bdc79000 ( 7.991 Tb) <unclassified> 0`7f0e0000 0`00f00000 ( 15.000 Mb) Image 0`77831000 0`00102000 ( 1.008 Mb) Stack 0`00170000 0`000fb000 (1004.000 kb) MemoryMappedFile 0`7efe5000 0`000fb000 (1004.000 kb) TEB 7ff`fffdc000 0`00002000 ( 8.000 kb) PEB 7ff`fffd3000 0`00001000 ( 4.000 kb)

Examination of such regions for Execution Residue such as Module Hint may point into further troubleshooting directions especially if live debugging is not possible.

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Pattern Models, Software Defect Construction, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 13k)

Monday, October 27th, 2014

While working on Insufficient Memory pattern for stack trace database we noticed the expansion of certain memory regions. Of course, after some time expanding region consumes remaining free or reserved space available before some other region. Generalizing from this we may say there can be Insufficient Memory pattern variant for any region expanding region. Region expansion may also be implemented via its move into some over position in memory virtual address space. This movement also has its limits. for example, we created this modeling application and found out it stops reallocating memory long before it reaches 2,000,000,000 byte size:

int _tmain(int argc, _TCHAR* argv[])
{
	int i = 100000000;

	void *p = malloc(i);

	for (i = 200000000; i < 2000000000; i+=100000000)
	{
		p = realloc(p, i);
		getc(stdin);
	}

	return 0;
}

We took memory dumps after each loop iteration and after 6 or 8 iterations the memory size was constant and there were no further reallocations:

0:000> !heap -s [...] Virtual block: 0000000006370000 - 0000000006370000 (size 0000000000000000) [...]

0:000> !address [...] + 0`00550000 0`06370000 0`05e20000 MEM_FREE PAGE_NOACCESS Free + 0`06370000 0`1222d000 0`0bebd000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block] + 0`1222d000 0`77710000 0`654e3000 MEM_FREE PAGE_NOACCESS Free + 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”] […]

0:000> !heap -s [...] Virtual block: 0000000012230000 - 0000000012230000 (size 0000000000000000) [...]

0:000> !address [...] + 0`005d0000 0`12230000 0`11c60000 MEM_FREE PAGE_NOACCESS Free + 0`12230000 0`2404b000 0`11e1b000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block] + 0`2404b000 0`77710000 0`536c5000 MEM_FREE PAGE_NOACCESS Free + 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”] […]

0:000> !heap -s [...] Virtual block: 0000000024050000 - 0000000024050000 (size 0000000000000000) [...]

0:000> !address [...] + 0`00590000 0`24050000 0`23ac0000 MEM_FREE PAGE_NOACCESS Free + 0`24050000 0`3bdc9000 0`17d79000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block] + 0`3bdc9000 0`77710000 0`3b947000 MEM_FREE PAGE_NOACCESS Free + 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”] […]

We skip a few iterations and finally come to a region that will not move and not increase:

0:000> !heap -s [...] Virtual block: 0000000041d30000 - 0000000041d30000 (size 0000000000000000) [...]

0:000> !address [...] + 0`006c0000 0`41d30000 0`41670000 MEM_FREE PAGE_NOACCESS Free + 0`41d30000 0`6b8c3000 0`29b93000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Heap [ID: 0; Handle: 0000000000310000; Type: Large block] + 0`6b8c3000 0`77710000 0`0be4d000 MEM_FREE PAGE_NOACCESS Free + 0`77710000 0`77711000 0`00001000 MEM_IMAGE MEM_COMMIT PAGE_READONLY Image [kernel32; “C:\windows\system32\kernel32.dll”] […]

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Pattern Models, Software Defect Construction, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 13j)

Monday, October 27th, 2014

Once we have seen a sequence of process memory dumps with the largest one almost 4GB. They were all saved from the process with growing memory consumption from 200MB initially. Initially we suspected process heap Memory Leak. However, heap statistics (!heap -s) was normal. There were not even large block allocations. The dumps were also supplied with UMDH logs but their difference only showed Memory Fluctuation and not increase. Stack Trace Collection revealed one Spiking Thread was logging a heap allocation into user mode stack trace database. We could also see that it was Distributed Spike. Inspection of address space showed large number of sequential regions of the same size with Stack Trace Database entries inside. So we concluded that it was stack trace logging Instrumentation Side Effect and advised to limit stack backtrace size in gflags.exe.

To make sure we understood that problem correctly we decided to model it. We didn’t come to the same results probably due to different logging implementation but memory dumps clearly show the possibility of Insufficient Memory pattern variant. Here’s the source code:

void foo20 (int size)
{
    free(malloc(size));
}

#define FOO(x,y) void foo##x (int size) { foo##y(size); }

FOO(19,20)
FOO(18,19)
FOO(17,18)
FOO(16,17)
FOO(15,16)
FOO(14,15)
FOO(13,14)
FOO(12,13)
FOO(11,12)
FOO(10,11)
FOO(9,10)
FOO(8,9)
FOO(7,8)
FOO(6,7)
FOO(5,6)
FOO(4,5)
FOO(3,4)
FOO(2,3)
FOO(1,2)

typedef void (*PFN) (int);

#define ARRSZ 20

PFN pfnArr[ARRSZ]  = {foo1, foo2, foo3, foo4, foo5, foo6, foo7,
    foo8, foo9, foo10, foo11, foo12, foo13, foo14,
    foo15, foo16, foo17, foo18, foo19, foo20};

int _tmain(int argc, _TCHAR* argv[])
{
    int i;

    for (i = 1; i < 1000000000; ++i) 
    {
        pfnArr[i%ARRSZ](i);
    }

    Sleep(-1); 
    return 0;
}

It allocates and then freezes heap entries of different size from 1 byte to 1,000,000,000 bytes all with different 20 possible stack traces. We choose different stack traces to increase the number of different {size, stack backtrace} pairs as several allocation of similar size having the same stack trace may be recorded only once in the database. We emulate different stack traces by calling different entries in pfnArr. Each call then leads to foo20 but the resulting stack trace depth is different. We also enabled “Create user mode stack trace database” checkbox in gflags.exe for our application called AllocFree.exe.

Then we see the expansion of Stack Trace Database regions (addresses are different because memory dumps were taken from different application runs):

0:000> !address [...] + 0`00240000 0`00312000 0`000d2000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database] 0`00312000 0`01a37000 0`01725000 MEM_PRIVATE MEM_RESERVE Other [Stack Trace Database] 0`01a37000 0`01a40000 0`00009000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database]

0:000> !address [...] + 0`001b0000 0`0188c000 0`016dc000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database] 0`0188c000 0`0188d000 0`00001000 MEM_PRIVATE MEM_RESERVE Other [Stack Trace Database] 0`0188d000 0`019b0000 0`00123000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database]

Heap stays the same:

0:000> !heap -s
NtGlobalFlag enables following debugging aids for new heaps:
stack back traces
LFH Key                   : 0x000000f841c4f9c0
Termination on corruption : ENABLED
           Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock
  Fast
                             (k)     (k)    (k)     (k) length      blocks cont.
 heap
-------------------------------------------------------------------------------
------
0000000001a40000 08000002    4096   1444   4096   1164     4     3    0      0
   LFH
External fragmentation  80 % (4 free blocks)
0000000000010000 08008000      64      4     64      1     1     1    0      0
0000000000020000 08008000      64     64     64     61     1     1    0      0
-------------------------------------------------------------------------------
------

0:000> !heap -s
NtGlobalFlag enables following debugging aids for new heaps:
stack back traces
LFH Key                   : 0x000000473a639107
Termination on corruption : ENABLED
           Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock
  Fast
                             (k)     (k)    (k)     (k) length      blocks cont.
 heap
-------------------------------------------------------------------------------
------
00000000019c0000 08000002    4096   1444   4096   1164     4     3    0      0
   LFH
External fragmentation  80 % (4 free blocks)
0000000000010000 08008000      64      4     64      1     1     1    0      0
0000000000020000 08008000      64     64     64     61     1     1    0      0
-------------------------------------------------------------------------------
------

But we see the thread consuming much CPU and caught while logging stack backtrace:

0:000> kc Call Site ntdll!RtlpStdLogCapturedStackTrace ntdll!RtlStdLogStackTrace ntdll!RtlLogStackBackTraceEx ntdll!RtlpAllocateHeap ntdll!RtlAllocateHeap AllocFree!_heap_alloc AllocFree!malloc AllocFree!foo20 AllocFree!foo19 AllocFree!foo18 AllocFree!foo17 AllocFree!foo16 AllocFree!foo15 AllocFree!foo14 AllocFree!foo13 AllocFree!foo12 AllocFree!foo11 AllocFree!foo10 AllocFree!foo9 AllocFree!foo8 AllocFree!foo7 AllocFree!foo6 AllocFree!foo5 AllocFree!foo4 AllocFree!foo3 AllocFree!foo2 AllocFree!foo1 AllocFree!wmain AllocFree!__tmainCRTStartup kernel32!BaseThreadInitThunk ntdll!RtlUserThreadStart

0:000> !runaway f
 User Mode Time
  Thread       Time
   0:53b8      0 days 3:22:02.354
 Kernel Mode Time
  Thread       Time
   0:53b8      0 days 0:20:39.022
 Elapsed Time
  Thread       Time
   0:53b8      0 days 10:11:23.596

If we dump some portion of the region we see recorded stack backtraces:

0:000> dps 0`0188c000-200 L200/8 00000000`0188be00 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd 00000000`0188be08 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c 00000000`0188be10 00000001`3fcc13cb AllocFree!malloc+0x5b 00000000`0188be18 00000001`3fcc1015 AllocFree!foo20+0x15 00000000`0188be20 00000001`3fcc1041 AllocFree!foo19+0x11 00000000`0188be28 00000001`3fcc1061 AllocFree!foo18+0x11 00000000`0188be30 00000001`3fcc12e3 AllocFree!wmain+0x53 00000000`0188be38 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144 00000000`0188be40 00000000`777259ed kernel32!BaseThreadInitThunk+0xd 00000000`0188be48 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d 00000000`0188be50 00000000`0188b1d0 00000000`0188be58 0009457d`00024fff 00000000`0188be60 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd 00000000`0188be68 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c 00000000`0188be70 00000001`3fcc13cb AllocFree!malloc+0x5b 00000000`0188be78 00000001`3fcc1015 AllocFree!foo20+0x15 00000000`0188be80 00000001`3fcc1041 AllocFree!foo19+0x11 00000000`0188be88 00000001`3fcc12e3 AllocFree!wmain+0x53 00000000`0188be90 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144 00000000`0188be98 00000000`777259ed kernel32!BaseThreadInitThunk+0xd 00000000`0188bea0 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d 00000000`0188bea8 00000000`00000000 00000000`0188beb0 00000000`0188b230 00000000`0188beb8 0008457e`00023fff 00000000`0188bec0 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd 00000000`0188bec8 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c 00000000`0188bed0 00000001`3fcc13cb AllocFree!malloc+0x5b 00000000`0188bed8 00000001`3fcc1015 AllocFree!foo20+0x15 00000000`0188bee0 00000001`3fcc12e3 AllocFree!wmain+0x53 00000000`0188bee8 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144 00000000`0188bef0 00000000`777259ed kernel32!BaseThreadInitThunk+0xd 00000000`0188bef8 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d 00000000`0188bf00 00000000`0188b280 00000000`0188bf08 001b457f`0002dfff 00000000`0188bf10 00000000`77891142 ntdll!RtlpAllocateHeap+0x33bd 00000000`0188bf18 00000000`778834d8 ntdll!RtlAllocateHeap+0x16c 00000000`0188bf20 00000001`3fcc13cb AllocFree!malloc+0x5b 00000000`0188bf28 00000001`3fcc1015 AllocFree!foo20+0x15 00000000`0188bf30 00000001`3fcc1041 AllocFree!foo19+0x11 00000000`0188bf38 00000001`3fcc1061 AllocFree!foo18+0x11 00000000`0188bf40 00000001`3fcc1081 AllocFree!foo17+0x11 00000000`0188bf48 00000001`3fcc10a1 AllocFree!foo16+0x11 00000000`0188bf50 00000001`3fcc10c1 AllocFree!foo15+0x11 00000000`0188bf58 00000001`3fcc10e1 AllocFree!foo14+0x11 00000000`0188bf60 00000001`3fcc1101 AllocFree!foo13+0x11 00000000`0188bf68 00000001`3fcc1121 AllocFree!foo12+0x11 00000000`0188bf70 00000001`3fcc1141 AllocFree!foo11+0x11 00000000`0188bf78 00000001`3fcc1161 AllocFree!foo10+0x11 00000000`0188bf80 00000001`3fcc1181 AllocFree!foo9+0x11 00000000`0188bf88 00000001`3fcc11a1 AllocFree!foo8+0x11 00000000`0188bf90 00000001`3fcc11c1 AllocFree!foo7+0x11 00000000`0188bf98 00000001`3fcc11e1 AllocFree!foo6+0x11 00000000`0188bfa0 00000001`3fcc1201 AllocFree!foo5+0x11 00000000`0188bfa8 00000001`3fcc1221 AllocFree!foo4+0x11 00000000`0188bfb0 00000001`3fcc1241 AllocFree!foo3+0x11 00000000`0188bfb8 00000001`3fcc1261 AllocFree!foo2+0x11 00000000`0188bfc0 00000001`3fcc1281 AllocFree!foo1+0x11 00000000`0188bfc8 00000001`3fcc12e3 AllocFree!wmain+0x53 00000000`0188bfd0 00000001`3fcc156c AllocFree!__tmainCRTStartup+0x144 00000000`0188bfd8 00000000`777259ed kernel32!BaseThreadInitThunk+0xd 00000000`0188bfe0 00000000`7785c541 ntdll!RtlUserThreadStart+0x1d 00000000`0188bfe8 00000000`00000000 00000000`0188bff0 00000000`00000000 00000000`0188bff8 00000000`00000000

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Pattern Models, Software Defect Construction, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 42m)

Thursday, October 23rd, 2014

Most if not all Wait Chain patterns are about waiting for some synchronization objects. Stack Traces of involved threads may point to Blocking and Top modules. In some situations we may consider a module (which functions were called) itself as a pseudo-synchronization object where a module (who called it) is waiting for it to return back (to become “signaled”). All this is problem and context dependent where some intermediate modules may be Pass Through or Well-Tested. When we see module inversion, such as in the case of callbacks we may provisionally suspect some kind of a deadlock and then investigate these threads in terms of synchronization objects or their corresponding source code:

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

Posted in Crash Dump Analysis, Crash Dump Patterns, Software Architecture | 1 Comment »

Crash Dump Analysis Patterns (Part 25d)

Tuesday, October 21st, 2014

Some troubleshooting and debugging techniques involve saving every Stack Trace that leads to a specific action such as a memory allocation of opening of a resource handle to be saved in some region in memory, called stack trace database. Typical pattern usage examples include Process Heap Memory Leak, Insufficient Memory due to Handle Leak. Typical entry in such a database consists of return addresses saved during function calls (which may be Truncated Stack Trace):

00000000`00325da0 000007fe`fd5e37aa KERNELBASE!InitializeCriticalSectionAndSpinCount+0xa 00000000`00325da8 00000001`3fd72239 AllocFree!_ioinit+0×2cd 00000000`00325db0 00000001`3fd71115 AllocFree!__tmainCRTStartup+0xc5 00000000`00325db8 00000000`773759ed kernel32!BaseThreadInitThunk+0xd 00000000`00325dc0 00000000`774ac541 ntdll!RtlUserThreadStart+0×1d

0:001> ub 00000001`3fd72239 AllocFree!_ioinit+0×2af: 00000001`3fd7221b cmp eax,3 00000001`3fd7221e jne AllocFree!_ioinit+0×2be (00000001`3fd7222a) 00000001`3fd72220 movsx eax,byte ptr [rbx+8] 00000001`3fd72224 or eax,8 00000001`3fd72227 mov byte ptr [rbx+8],al 00000001`3fd7222a lea rcx,[rbx+10h] 00000001`3fd7222e mov edx,0FA0h 00000001`3fd72233 call qword ptr [AllocFree!_imp_InitializeCriticalSectionAndSpinCount (00000001`3fd78090)

This slightly differs from ‘k’-style stack trace format where the return address belongs to the function on the next line if moving downwards:

0:000> k Child-SP RetAddr Call Site 00000000`002ff9f8 000007fe`fd5e1203 ntdll!ZwDelayExecution+0xa 00000000`002ffa00 00000001`3fd71018 KERNELBASE!SleepEx+0xab 00000000`002ffaa0 00000001`3fd71194 AllocFree!wmain+0×18 00000000`002ffad0 00000000`773759ed AllocFree!__tmainCRTStartup+0×144 00000000`002ffb10 00000000`774ac541 kernel32!BaseThreadInitThunk+0xd 00000000`002ffb40 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

0:000> ub 00000001`3fd71194 AllocFree!__tmainCRTStartup+0×11b: 00000001`3fd7116b je AllocFree!__tmainCRTStartup+0×124 (00000001`3fd71174) 00000001`3fd7116d mov ecx,eax 00000001`3fd7116f call AllocFree!_amsg_exit (00000001`3fd718ec) 00000001`3fd71174 mov r8,qword ptr [AllocFree!_wenviron (00000001`3fd80868)] 00000001`3fd7117b mov qword ptr [AllocFree!__winitenv (00000001`3fd80890)],r8 00000001`3fd71182 mov rdx,qword ptr [AllocFree!__wargv (00000001`3fd80858)] 00000001`3fd71189 mov ecx,dword ptr [AllocFree!__argc (00000001`3fd8084c)] 00000001`3fd7118f call AllocFree!wmain (00000001`3fd71000)

Sometimes we can see such traces as Execution Residue inside a stack or some other region. If user mode stack trace database is enabled in gflags.exe we might be able to dump the specific database region:

0:001> !gflag Current NtGlobalFlag contents: 0x00001000 ust - Create user mode stack trace database

0:001> !address [...] BaseAddress EndAddress+1 RegionSize Type State Protect Usage ------------------------------------------------------------------------------------------------------------------------ [...] + 0`00300000 0`00326000 0`00026000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database] 0`00326000 0`01aff000 0`017d9000 MEM_PRIVATE MEM_RESERVE Other [Stack Trace Database] 0`01aff000 0`01b00000 0`00001000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Other [Stack Trace Database] […]

0:001> dps 0`00326000-1000 0`00326000 […] 00000000`003257e0 00000000`00000000 00000000`003257e8 00030001`00001801 00000000`003257f0 00000000`774c34eb ntdll!LdrpInitializeProcess+0×7e6 00000000`003257f8 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325800 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325808 00000000`00000000 00000000`00325810 00000000`00000000 00000000`00325818 00030002`00001801 00000000`00325820 00000000`774c3511 ntdll!LdrpInitializeProcess+0×80c 00000000`00325828 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325830 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325838 00000000`00000000 00000000`00325840 00000000`00000000 00000000`00325848 00040003`00001801 00000000`00325850 00000000`774bda86 ntdll!RtlCreateHeap+0×506 00000000`00325858 00000000`774c3557 ntdll!LdrpInitializeProcess+0×851 00000000`00325860 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325868 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325870 00000000`00000000 00000000`00325878 00050004`00002801 00000000`00325880 00000000`7751998a ntdll! ?? ::FNODOBFM::`string’+0xdc1a 00000000`00325888 00000000`774bdaee ntdll!RtlCreateHeap+0×56e 00000000`00325890 00000000`774c3557 ntdll!LdrpInitializeProcess+0×851 00000000`00325898 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`003258a0 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`003258a8 00000000`00000000 00000000`003258b0 00000000`00000000 00000000`003258b8 00030005`00001801 00000000`003258c0 00000000`774c359e ntdll!LdrpInitializeProcess+0×902 00000000`003258c8 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`003258d0 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`003258d8 00000000`00000000 00000000`003258e0 00000000`00000000 00000000`003258e8 00030006`00001801 00000000`003258f0 00000000`774c35af ntdll!LdrpInitializeProcess+0×913 00000000`003258f8 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325900 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325908 00000000`00000000 00000000`00325910 00000000`00000000 00000000`00325918 00090007`00004801 00000000`00325920 00000000`774bda86 ntdll!RtlCreateHeap+0×506 00000000`00325928 00000000`774c47ff ntdll!CsrpConnectToServer+0×41f 00000000`00325930 00000000`774c43c5 ntdll!CsrClientConnectToServer+0×230 00000000`00325938 000007fe`fd5ee232 KERNELBASE!KernelBaseDllInitialize+0×148 00000000`00325940 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325948 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325950 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325958 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325960 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325968 00000000`00000000 00000000`00325970 00000000`00000000 00000000`00325978 000a0008`00004801 00000000`00325980 00000000`7751998a ntdll! ?? ::FNODOBFM::`string’+0xdc1a 00000000`00325988 00000000`774bdaee ntdll!RtlCreateHeap+0×56e 00000000`00325990 00000000`774c47ff ntdll!CsrpConnectToServer+0×41f 00000000`00325998 00000000`774c43c5 ntdll!CsrClientConnectToServer+0×230 00000000`003259a0 000007fe`fd5ee232 KERNELBASE!KernelBaseDllInitialize+0×148 00000000`003259a8 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`003259b0 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`003259b8 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`003259c0 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`003259c8 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`003259d0 00000000`00000000 00000000`003259d8 00080009`00003801 00000000`003259e0 000007fe`fd5edf81 KERNELBASE!NlsProcessInitialize+0×11 00000000`003259e8 000007fe`fd604439 KERNELBASE!BaseNlsDllInitialize+0×29 00000000`003259f0 000007fe`fd5ee446 KERNELBASE!KernelBaseDllInitialize+0×40c 00000000`003259f8 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325a00 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325a08 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325a10 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325a18 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325a20 00000000`00000000 00000000`00325a28 0008000a`00003801 00000000`00325a30 000007fe`fd5edfa0 KERNELBASE!NlsProcessInitialize+0×30 00000000`00325a38 000007fe`fd604439 KERNELBASE!BaseNlsDllInitialize+0×29 00000000`00325a40 000007fe`fd5ee446 KERNELBASE!KernelBaseDllInitialize+0×40c 00000000`00325a48 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325a50 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325a58 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325a60 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325a68 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325a70 00000000`00000000 00000000`00325a78 0007000b`00003801 00000000`00325a80 000007fe`fd604a21 KERNELBASE!BasepInitComputerNameCache+0×11 00000000`00325a88 000007fe`fd603d20 KERNELBASE!KernelBaseDllInitialize+0×419 00000000`00325a90 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325a98 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325aa0 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325aa8 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325ab0 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325ab8 00000000`00000000 00000000`00325ac0 00000000`00000000 00000000`00325ac8 0006000c`00002801 00000000`00325ad0 00000000`77375699 kernel32!BaseDllInitialize+0×2f9 00000000`00325ad8 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325ae0 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325ae8 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325af0 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325af8 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325b00 00000000`00000000 00000000`00325b08 0007000d`00003801 00000000`00325b10 00000000`773771f7 kernel32!InitializeConsoleConnectionInfo+0xe7 00000000`00325b18 00000000`773756ae kernel32!BaseDllInitialize+0×30e 00000000`00325b20 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325b28 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325b30 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325b38 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325b40 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325b48 00000000`00000000 00000000`00325b50 00000000`00000000 00000000`00325b58 0009000e`00004801 00000000`00325b60 00000000`774bda86 ntdll!RtlCreateHeap+0×506 00000000`00325b68 00000000`773787f7 kernel32!ConsoleConnect+0×1d7 00000000`00325b70 00000000`773770de kernel32!ConnectConsoleInternal+0×147 00000000`00325b78 00000000`773756fe kernel32!BaseDllInitialize+0×35e 00000000`00325b80 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325b88 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325b90 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325b98 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325ba0 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325ba8 00000000`00000000 00000000`00325bb0 00000000`00000000 00000000`00325bb8 000a000f`00004801 00000000`00325bc0 00000000`7751998a ntdll! ?? ::FNODOBFM::`string’+0xdc1a 00000000`00325bc8 00000000`774bdaee ntdll!RtlCreateHeap+0×56e 00000000`00325bd0 00000000`773787f7 kernel32!ConsoleConnect+0×1d7 00000000`00325bd8 00000000`773770de kernel32!ConnectConsoleInternal+0×147 00000000`00325be0 00000000`773756fe kernel32!BaseDllInitialize+0×35e 00000000`00325be8 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325bf0 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325bf8 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325c00 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325c08 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325c10 00000000`00000000 00000000`00325c18 00060010`00002801 00000000`00325c20 00000000`773757dc kernel32!BaseDllInitialize+0×43c 00000000`00325c28 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325c30 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325c38 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325c40 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325c48 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325c50 00000000`00000000 00000000`00325c58 00060011`00002801 00000000`00325c60 00000000`7737582c kernel32!BaseDllInitialize+0×48c 00000000`00325c68 00000000`774bb108 ntdll!LdrpRunInitializeRoutines+0×1fe 00000000`00325c70 00000000`774c42fd ntdll!LdrGetProcedureAddressEx+0×2aa 00000000`00325c78 00000000`774c1ddc ntdll!LdrpInitializeProcess+0×1a0b 00000000`00325c80 00000000`774c1937 ntdll! ?? ::FNODOBFM::`string’+0×28ff0 00000000`00325c88 00000000`774ac34e ntdll!LdrInitializeThunk+0xe 00000000`00325c90 00000000`00000000 00000000`00325c98 00060012`0000280e 00000000`00325ca0 000007fe`fd5e37aa KERNELBASE!InitializeCriticalSectionAndSpinCount+0xa 00000000`00325ca8 00000001`3fd7319f AllocFree!_mtinitlocks+0×43 00000000`00325cb0 00000001`3fd717fc AllocFree!_mtinit+0×10 00000000`00325cb8 00000001`3fd710e4 AllocFree!__tmainCRTStartup+0×94 00000000`00325cc0 00000000`773759ed kernel32!BaseThreadInitThunk+0xd 00000000`00325cc8 00000000`774ac541 ntdll!RtlUserThreadStart+0×1d 00000000`00325cd0 00000000`00000000 00000000`00325cd8 000b0013`00005801 00000000`00325ce0 00000000`774c1131 ntdll!RtlpActivateLowFragmentationHeap+0×181 00000000`00325ce8 00000000`774c0f97 ntdll!RtlpPerformHeapMaintenance+0×27 00000000`00325cf0 00000000`774c0f5b ntdll!RtlpAllocateHeap+0×1819 00000000`00325cf8 00000000`774d34d8 ntdll!RtlAllocateHeap+0×16c 00000000`00325d00 00000000`774a9300 ntdll!RtlInitializeCriticalSectionAndSpinCount+0×183 00000000`00325d08 000007fe`fd5e37aa KERNELBASE!InitializeCriticalSectionAndSpinCount+0xa 00000000`00325d10 00000001`3fd7319f AllocFree!_mtinitlocks+0×43 00000000`00325d18 00000001`3fd717fc AllocFree!_mtinit+0×10 00000000`00325d20 00000001`3fd710e4 AllocFree!__tmainCRTStartup+0×94 00000000`00325d28 00000000`773759ed kernel32!BaseThreadInitThunk+0xd 00000000`00325d30 00000000`774ac541 ntdll!RtlUserThreadStart+0×1d 00000000`00325d38 00000000`00000000 00000000`00325d40 00000000`00000000 00000000`00325d48 00070014`00003801 00000000`00325d50 000007fe`fd5e37aa KERNELBASE!InitializeCriticalSectionAndSpinCount+0xa 00000000`00325d58 00000001`3fd7312f AllocFree!_mtinitlocknum+0×8f 00000000`00325d60 00000001`3fd72ff7 AllocFree!_lock+0×23 00000000`00325d68 00000001`3fd71f9b AllocFree!_ioinit+0×2f 00000000`00325d70 00000001`3fd71115 AllocFree!__tmainCRTStartup+0xc5 00000000`00325d78 00000000`773759ed kernel32!BaseThreadInitThunk+0xd 00000000`00325d80 00000000`774ac541 ntdll!RtlUserThreadStart+0×1d 00000000`00325d88 00000000`00000000 00000000`00325d90 00000000`00000000 00000000`00325d98 00050015`00002803 00000000`00325da0 000007fe`fd5e37aa KERNELBASE!InitializeCriticalSectionAndSpinCount+0xa 00000000`00325da8 00000001`3fd72239 AllocFree!_ioinit+0×2cd 00000000`00325db0 00000001`3fd71115 AllocFree!__tmainCRTStartup+0xc5 00000000`00325db8 00000000`773759ed kernel32!BaseThreadInitThunk+0xd 00000000`00325dc0 00000000`774ac541 ntdll!RtlUserThreadStart+0×1d 00000000`00325dc8 00000000`00000000 00000000`00325dd0 00000000`00000000 […]

This database corresponds to this simple program:

int _tmain(int argc, _TCHAR* argv[])
{
    free(malloc(256));
    Sleep(-1);
    return 0;
}

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

Posted in Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 25c)

Sunday, October 12th, 2014

Sometimes threads related to file system operations may be blocked with not easily recognizable 3rd-party Top Module with only OS vendor modules such as NTFS or fltmgr present:

nt!KiSwapContext+0x7a nt!KiCommitThreadWait+0x1d2 nt!KeWaitForSingleObject+0x19f nt!FsRtlCancellableWaitForMultipleObjects+0x5e nt!FsRtlCancellableWaitForSingleObject+0x27 fltmgr! ?? ::FNODOBFM::`string’+0×2bfa fltmgr!FltpCreate+0×2a9 nt!IopParseDevice+0×14d3 nt!ObpLookupObjectName+0×588 nt!ObOpenObjectByName+0×306 nt!IopCreateFile+0×2bc nt!NtCreateFile+0×78 nt!KiSystemServiceCopyEnd+0×13 ntdll!NtCreateFile+0xa […]

We see the same modules in I/O Request Stack Trace from the thread IRP. But because we see filter manager involved there may be some 3rd-party file system filters involved. Such filters are called before a device processes a request and also upon the completion of the request. There may be different filter callbacks registered for each case and they form a similar structure like I/O stack locations (we call this pattern Filter Stack Trace):

If one of such filters is blocked in a wait chain this may not be visible on I/O request or thread stacks because of possible asynchronous processing. But we may use !fltkd.irpctrl debugging extension command to examine the IRP context:

0: kd> !irp fffffa80162aa230 cmd flg cl Device File Completion-Context [...] [ 0, 0] 0 0 fffffa800cb28030 00000000 fffff880012048f0-fffffa8016f64010 \FileSystem\Ntfs fltmgr!FltpSynchronizedOperationCompletion Args: 00000000 00000000 00000000 00000000 >[ 0, 0] 0 1 fffffa800ca00890 fffffa801060d070 00000000-00000000 pending \FileSystem\FltMgr Args: fffff88014450868 02000060 00000006 00000000

0: kd> !fltkd.irpctrl fffffa8016f64010 [...] Cmd IrpFl OpFl CmpFl Instance FileObjt Completion-Context Node Adr --------- -------- ----- ----- -------- -------- ------------------ -------- [0,0] 00000884 00 0000 fffffa800d29c010 fffffa801060d070 fffff8800518b474-0000000000000000 fffffa8016f641e0 ("luafv","luafv") luafv!LuafvPostCreate Args: fffff88014450868 0000000002000060 0000000000000006 0000000000000000 0000000000000000 0000000000000000 >[0,0] 00000884 00 0000 fffffa800e8051d0 fffffa801060d070 fffff88006808440-0000000000000000 fffffa8016f64160 (”3rdPartyFilter”,”3rdPartyFilter Instance”) FilterA!FltDriver_PostOperationCallback Args: fffff88014450868 0000000002000060 0000000000000006 0000000000000000 0000000000000000 0000000000000000 […]

So we see that FilterA module may be involved in blocking the thread (Blocking Module pattern extended to I/O request and filter stack traces).

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

Posted in Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 25b)

Sunday, October 12th, 2014

If a thread has an associated I/O Request Packet (IRP) we may see another type of a stack trace we call I/O Request Stack Trace. It also grows bottom-up as can be seen on the diagram 3. We can see this stack trace by using !irp WinDbg command:

0: kd> !thread fffffa801827a4c0 3f THREAD fffffa801827a4c0 Cid 06c0.50cc Teb: 000007ffffec8000 Win32Thread: fffff900c1c64010 WAIT: (Executive) KernelMode Alertable fffffa8016f64028 SynchronizationEvent IRP List: fffffa80162aa230: (0006,03a0) Flags: 00000884 Mdl: 00000000 […] nt!KiSwapContext+0×7a nt!KiCommitThreadWait+0×1d2 nt!KeWaitForSingleObject+0×19f nt!FsRtlCancellableWaitForMultipleObjects+0×5e nt!FsRtlCancellableWaitForSingleObject+0×27 fltmgr! ?? ::FNODOBFM::`string’+0×2bfa fltmgr!FltpCreate+0×2a9 nt!IopParseDevice+0×14d3 nt!ObpLookupObjectName+0×588 nt!ObOpenObjectByName+0×306 nt!IopCreateFile+0×2bc nt!NtCreateFile+0×78 nt!KiSystemServiceCopyEnd+0×13 ntdll!NtCreateFile+0xa […]

0: kd> !irp fffffa80162aa230 Irp is active with 10 stacks 10 is current (= 0xfffffa80162aa588) No Mdl: No System Buffer: Thread fffffa801827a4c0: Irp stack trace. cmd flg cl Device File Completion-Context [ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 fffffa800cb28030 00000000 fffff880012048f0-fffffa8016f64010 \FileSystem\Ntfs fltmgr!FltpSynchronizedOperationCompletion Args: 00000000 00000000 00000000 00000000 >[ 0, 0] 0 1 fffffa800ca00890 fffffa801060d070 00000000-00000000 pending \FileSystem\FltMgr Args: fffff88014450868 02000060 00000006 00000000

We see the current stack trace pointer points to the bottom I/O stack location. Non-empty top locations are analogous to Past Stack Trace. Further exploration of Device and File column information may point to further troubleshooting directions such as the Blocking File pattern example.

By analogy with Stack Trace Collection pattern that dumps stack traces from all threads based on memory dump type there is also I/O Stack Trace Collection pattern that dumps I/O request stack traces from all IRPs that were possible to find.

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

Posted in Crash Dump Analysis, Crash Dump Patterns, x64 Windows | No Comments »

Crash Dump Analysis Patterns (Part 214)

Wednesday, October 8th, 2014

When we look at a stack trace in a memory dump we see only the current thread execution snapshot of function calls. Consider this stack trace, for example, from Spiking Thread:

0:000> k Child-SP RetAddr Call Site 00000000`0012d010 00000000`76eb59ed App!WinMain+0x1eda 00000000`0012f7c0 00000000`770ec541 kernel32!BaseThreadInitThunk+0xd 00000000`0012f7f0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

By looking at Rough Stack Trace we may be able to reconstruct Past Stack Trace of what had happened just before the memory snapshot was taken:

0:000> k Child-SP RetAddr Call Site 00000000`0012cfd8 00000000`76fd9e9e user32!ZwUserGetMessage+0xa 00000000`0012cfe0 00000000`ffd91a8c user32!GetMessageW+0x34 00000000`0012d010 00000000`76eb59ed App!WinMain+0x1dca 00000000`0012f7c0 00000000`770ec541 kernel32!BaseThreadInitThunk+0xd 00000000`0012f7f0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

The stack region “time” zones are illustrated on the following picture:

The “Future” zone takes its name from the not yet executed returns. Of course, each stack subtrace generates its own partition. A similar version of this pattern was first introduced in Debugging TV Frames episode 0×24. You watch the video here and can find source code, WinDbg logs, and presentation here.

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

Posted in Core Dump Analysis, Crash Dump Analysis, Crash Dump Patterns | No Comments »

May 2026
M	T	W	T	F	S	S
« Mar
				1	2	3
4	5	6	7	8	9	10
11	12	13	14	15	16	17
18	19	20	21	22	23	24
25	26	27	28	29	30	31

Archive for the ‘Crash Dump Patterns’ Category

Pages

Recent Comments

Categories

Archives

ARM64

Automated Analysis

Blogroll

Debugging Channels

Forensics

Hardware

Linux

Mac OS X

Magazines and Newspapers

Malware Analysis

Medical Diagnostics

Narratology

Related Links

Reversing

Scripting Languages

Source Code

Tracing Tools

Meta