Archive for March, 2015

Win32 Start Address Fallacy

Tuesday, March 17th, 2015

One of the common mistakes is not double-checking symbolic output. Another example here is related to Win32 Start Address. In the output of !thread WinDbg command (or !process and !sprocess Stack Trace Collection commands) we can see Win32 Start Address and, in cases of Truncated Stack Traces or No Component Symbols, we may use this information to guess the purpose of the thread. Unfortunately, it is shown without function offsets and may give a false sense of the thread purpose. For example, this Win32 Start Address ModuleA!DoSomething may suggest that the purpose of the thread was to DoSomething:

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: ServiceA.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 ModuleA!DoSomething (0×000007fef46b4cde)
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 000007fe`f46a4afe ntdll!NtWaitForSingleObject+0xa
00000000`0427ccb0 000007fe`f46c68d4 ModuleA!DoSomething+0xc68d4
00000000`0427cd60 000007fe`f46c6ade ModuleA!DoSomething+0xc5ee8

But if we look at fragments of the stack trace we see function huge offsets and this means that this function was just some function from ModuleA export table. It was chosen because return addresses fall into an address range between exported functions. Because Win32 Start Address also falls into such an address range it is listed as ModuleA!DoSomething but without an offset. In our case, an engineer made the wrong assumption about the possible root cause and provided unnecessary troubleshooting instructions.

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

Trace Analysis Patterns (Part 104)

Tuesday, March 17th, 2015

Trace Mask is a superposition of two (or many) different traces. This is different from Inter-Correlation pattern where we may only search for certain messages without the synthesis of a new log. The most useful Trace Mask is when we have different time scales (or significantly different Trace Currents). Then we impose an additional structure on the one of the traces:

We got the idea from Narrative Masks discussed in Miroslav Drozda’s book “Narativní masky ruské prózy” (”Narrative Masks in Russian Prose”).

The very simple example of Trace Mask is shown in Debugging TV Episode 0×15.

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

Trace Analysis Patterns (Part 103)

Saturday, March 14th, 2015

Sometimes we have a uniform stream of messages that belong to some Activity Region, Thread of Activity, or Adjoint Thread of Activity. We can use micro-Discontinuities to structure that message stream into groups of actions, for example, Macrofunctions, especially if semantics of trace messages is not yet fully clear to us. This may also help us to recognize Visitor trace. Originally we wanted to call this pattern Micro Delays, but, after recognizing that such delays only make sense for one activity (since there can be too many of them in the overall log), we named this pattern Punctuated Activity. Usually such delays are small compare to Timeouts and belong to Silent Messages.

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

Crash Dump Analysis Patterns (Part 223)

Saturday, March 7th, 2015

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

0: kd> !process 0 0

[...]

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

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

[...]

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

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

Trace Analysis Patterns (Part 102)

Tuesday, March 3rd, 2015

When we do tracing and logging much of computational activity is not visible. For live tracing and debugging this can be alleviated by adding Watch Threads. These are selected memory locations that may or may not be formatted according to specific data structures and are inspected at each main trace message occurrence or after specific intervals or events:

This analysis pattern is different from State Dump which is about intrinsic tracing where the developer of logging statements already incorporated variable watch in source code. Watch Threads are completely independent from original tracing and may be added independently. Counter Value is the simplest example of Watch Thread if done externally because the former usually doesn’t require source code and often means some OS or module variable independent of product internals. Watch Thread is also similar to Data Flow pattern where specific data we are interested in is a part of every trace message.

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