Software Diagnostics Library

Crash Dump Analysis Patterns (Part 222)

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 »

Trace Analysis Patterns (Part 101)

February 22nd, 2015

Sometimes we have Basic Facts in a problem description but can’t find messages corresponding to them in a trace or log file but we are sure the tracing (logging) was done correctly. This may be because we have Sparse Trace, or we are not familiar well with product or system tracing messages (such as with Implementation Discourse).

In such a case we for search for Indirect Message of a possible cause:

Having found such a message we may hypothesize that Missing Message should have located nearby (this is based on semantics of both messages), and we then explore corresponding Message Context:

The same analysis strategy is possible for missing causal messages. Here we search for effect or side effect messages:

Having found them we proceed with further analysis:

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

Posted in CDF Analysis Tips and Tricks, Log Analysis, Software Trace Analysis, Software Trace Analysis Tips and Tricks, Trace Analysis Patterns | No Comments »

Crash Dump Analysis Patterns (Part 221)

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)

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)

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)

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 »

Trace Analysis Patterns (Part 99)

January 24th, 2015

Sometimes specific parts of simultaneous Use Case Trails, blocks of Significant Events or Message Sets in general may overlap. This may point to possible synchronization problems such as race conditions (prognostics) or be visible root causes of them if such problems are reported (diagnostics). We call this pattern Activity Overlap:

For example, a first request may start a new session and we expect the second request to be processed by the same already established session:

However, users report the second session started upon the second request. If we filter execution log by session id and do Intra-Correlational analysis we find out that session initialization prologues are overlapped. The new session started because the first session initialization was not completed:

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

Posted in CDF Analysis Tips and Tricks, Debugging, Log Analysis, Software Prognostics, Software Trace Analysis, Trace Analysis Patterns | No Comments »

Trace Analysis Patterns (Part 98)

January 7th, 2015

Some Discontinuities may be Periodic as Silent Messages. If such discontinuities belong to the same Thread of Activity and their Time Deltas are constant we may see Timeout pattern. When timeouts are followed by Error Message we can identify them by back tracing. Timeouts are different from Blackouts where the latter are usually Singleton Events and have large time deltas.

Here is a generalized graphical case study. An error message was identified based on incident Basic Facts:

We filtered the trace for error message TID and found 3 timeouts 30 minutes each:

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

Posted in Debugging, Log Analysis, Software Trace Analysis, Trace Analysis Patterns | No Comments »

Crash Dump Analysis Patterns (Part 218)

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)

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 »

Trace Analysis Patterns (Part 97)

November 29th, 2014

Some traces and logs may have Periodic Message Blocks with very similar message structure and content (mostly Message Invariants). The only significant difference between them is some unique data. We call such pattern Visitor Trace by analogy with Visitor design pattern where tracing code “visits” each object data or data part to log its content or status.

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

Posted in Log Analysis, Software Engineering, Software Trace Analysis, Software Trace Reading, Trace Analysis Patterns, Tracing and Design Patterns | No Comments »

Trace Analysis Patterns (Part 96)

November 19th, 2014

There are events that by design or system configuration should be seen in a log only once or not seen at all if code responsible for them was executed before tracing session. For example, the launch of certain services during system initialization shouldn’t be seen again when we trace system activity long after that. It can also be just messages from singleton objects in the application log. The appearance of extra Singleton Events may point to design violations or some abnormal system events such as process restart. The latter may Intra-Correlate with the start of the fault handling process such as WerFault.exe in Windows Process Monitor logs (Guest Component).

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

Posted in Log Analysis, Software Engineering, Software Trace Analysis, Software Trace Analysis Tips and Tricks, Software Trace Reading, Trace Analysis Patterns, Tracing and Design Patterns | No Comments »

Crash Dump Analysis Patterns (Part 216)

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)

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 »

Trace Analysis Patterns (Part 95)

November 16th, 2014

Trace and log analysis starts with assessment of artifact File Size, especially with multiple logging scenarios in distributed systems. If all log files are of the same size we might have either Circular Traces or Truncated Traces. Both point to wrong trace timing plan or just using default tracing tool configuration.

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

Posted in CDF Analysis Tips and Tricks, Software Trace Analysis, Software Trace Analysis Tips and Tricks, Trace Acquisition Patterns, Trace Analysis Patterns, Trace Analysis and Topology | No Comments »

Crash Dump Analysis Patterns (Part 61b)

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 »

Trace Analysis Patterns (Part 94)

November 11th, 2014

Trace messages may correspond to specific implementation code such as recording the status of an operation, dumping data values, printing errors, or they may correspond to higher levels of software design and architecture, and even to use case stories. We call such messages Milestones by analogy with project management. Alternative names can be Chapter Messages, Summary Messages, Checkpoints, or Use Case Messages. These are different from Macrofunctions which are collections messages grouped by some higher function. Milestone messages are specifically designed distinct trace statements:

They can also be a part of Significant Events, serve the role of Anchor Messages, and be a part of Basic Facts and Vocabulary Index.

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

Posted in CDF Analysis Tips and Tricks, Software Narratology, Software Trace Analysis, Software Trace Reading, Software Tracing Design, Trace Analysis Patterns | No Comments »

Trace Analysis Patterns (Part 93)

November 9th, 2014

Sometimes we have several use case instances traced in one log file. Messages and Activity Regions from many Use Case Trails intermingle and make analysis difficult especially with the absence of UCID (Use Case ID), any other identification tags, or Message Links. However, initially most of the time we are interested in a sequence of Significant Events. After finding Anchor Messages we can use Time Deltas to differentiate between trace statements from different Use Case Trails. Here we assume correct Event Sequence Order. We call this pattern Event Sequence Phase by analogy with wave phases (all such individual “waves” may have different “shapes” due to various delays between different stages of their use case and implementation narratives):

In the picture above we also identified Dominant Event Sequence for use case instance C.

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

Posted in CDF Analysis Tips and Tricks, Software Trace Analysis, Software Trace Analysis Tips and Tricks, Software Trace Reading, Trace Analysis Patterns, Trace Analysis and Physics | No Comments »

Trace Analysis Patterns (Part 92)

November 9th, 2014

Use cases are implemented in various components such as subsystems, processes, modules, and source code files. Most of the time with good tracing implementation we are able to see Use Case Trails: log messages corresponding to use case scenarios. For simple systems one log may fully correspond to just one use case, but for complex systems, especially distributed client-server ones, there may be several use case instances present simultaneously in one log. One way to disentangle them in the absence of UCID (Use Case ID) or some other grouping tag is to use Event Sequence Phase, the subject of the next pattern.

Master Traces may also correspond to use cases but they should ideally correspond to only one use case instance.

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

Posted in CDF Analysis Tips and Tricks, Debugging, Log Analysis, Software Architecture, Software Trace Analysis, Software Trace Deconstruction, Software Trace Reading, Trace Analysis Patterns | No Comments »

Crash Dump Analysis Patterns (Part 20e)

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 »

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

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