Archive for November, 2014

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 -

Trace Analysis Patterns (Part 97)

Saturday, 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 -

Trace Analysis Patterns (Part 96)

Wednesday, 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 -

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 -

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 -

Trace Analysis Patterns (Part 95)

Sunday, 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 -

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 -

Trace Analysis Patterns (Part 94)

Tuesday, 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 -

Trace Analysis Patterns (Part 93)

Sunday, 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 -

Trace Analysis Patterns (Part 92)

Sunday, 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 -