Archive for March, 2013

Fool (Debugging Slang, Part 38)

Sunday, March 31st, 2013

Fool - The long version of a foo program used in C and C++ tutorials.

Examples: What a foolish program!

- Dmitry Vostokov @ + -

Generalized Software Narrative and Trace

Monday, March 25th, 2013

In the past we viewed software traces and logs as temporarily ordered event sequences. Since events are just memory data we have a map

T  -> M

as can be seen in the definition of a software trace. Here we generalize the domain to any arbitrary set, for example, it can be a list of indexes or pointers or even memory itself. The latter map can give us narrative chains such as

M -> M -> M -> M

and even give us a grand unification of memory and log analysis and the possibility to apply software narratology to memory dump analysis as well. We talk about it soon and provide some generalized software narrative examples.

- Dmitry Vostokov @ + -

Trace Analysis Patterns (Part 68)

Saturday, March 23rd, 2013

While preparing a presentation on malware narratives we found that one essential pattern is missing from the current log analysis pattern catalog. Most of the time we see some abnormal or unexpected value in a software trace or log such as a network address outside expected range and this triggers further investigation. The message structure may be the same having the same Message Invariant but variable part may contain such values as depicted graphically:

We call this pattern Abnormal Value and plan to add the similar one to memory dump analysis pattern catalog. Please not that we also have Significant Event pattern that is more general and also covers messages without variable part or just suspicious log entries.

- Dmitry Vostokov @ + -

More 10 Common Mistakes in Memory Analysis (Part 1)

Friday, March 22nd, 2013

Because we finished the list of 10 common mistakes some time ago we continue with “more” series. A year ago we discovered the need to pay attention to differences between 32-bit and 64-bit versions of critical section structures and the need for explicit symbol qualification in x86 mode to avoid mistakes. This post was in draft since then and we now publish it. Suppose we see the address of a critical section on a 32-bit stack trace:

0:000:x86> kv
ChildEBP RetAddr  Args to Child
0044f40c 774e8dd4 00000a94 00000000 00000000 ntdll_774b0000!ZwWaitForSingleObject+0x15
0044f470 774e8cb8 00000000 00000000 041f4b78 ntdll_774b0000!RtlpWaitOnCriticalSection+0x13e
0044f498 0123f70c 010d97c0 8c62ec9c 010cc5fc ntdll_774b0000!RtlEnterCriticalSection+0×150

0:000:x86> dt _RTL_CRITICAL_SECTION 010d97c0
+0x000 DebugInfo        : 0x00862680 _RTL_CRITICAL_SECTION_DEBUG
+0x008 LockCount        : 0n1
+0x00c RecursionCount   : 0n103356
+0×010 OwningThread     : 0×00000a94 Void
+0×018 LockSemaphore    : 0×0817d72d Void
+0×020 SpinCount        : 0×6130910c`010d9840

Its owner thread has a94 TID but we don’t see it in the thread list:

0:000:x86> ~
.  0  Id: 19508.17944 Suspend: 0 Teb: 7efdb000 Unfrozen
1  Id: 19508.1922c Suspend: 0 Teb: 7efd8000 Unfrozen
2  Id: 19508.195d4 Suspend: 0 Teb: 7efd5000 Unfrozen
3  Id: 19508.19a80 Suspend: 0 Teb: 7efa7000 Unfrozen
4  Id: 19508.19544 Suspend: 0 Teb: 7efa4000 Unfrozen
5  Id: 19508.1925c Suspend: 0 Teb: 7efa1000 Unfrozen
6  Id: 19508.193d4 Suspend: 0 Teb: 7ef9d000 Unfrozen
7  Id: 19508.19b18 Suspend: 0 Teb: 7ef9a000 Unfrozen
8  Id: 19508.19bfc Suspend: 0 Teb: 7ef97000 Unfrozen
9  Id: 19508.19bc4 Suspend: 0 Teb: 7ef94000 Unfrozen
10  Id: 19508.19a90 Suspend: 0 Teb: 7ef91000 Unfrozen
11  Id: 19508.189c0 Suspend: 0 Teb: 7ef8d000 Unfrozen
12  Id: 19508.193bc Suspend: 0 Teb: 7ef8a000 Unfrozen
13  Id: 19508.18f3c Suspend: 0 Teb: 7ef87000 Unfrozen
14  Id: 19508.18834 Suspend: 0 Teb: 7ef84000 Unfrozen
15  Id: 19508.19aec Suspend: 0 Teb: 7ef81000 Unfrozen
16  Id: 19508.180f4 Suspend: 0 Teb: 7ef7d000 Unfrozen
17  Id: 19508.19a3c Suspend: 0 Teb: 7ef7a000 Unfrozen
18  Id: 19508.1916c Suspend: 0 Teb: 7ef77000 Unfrozen
19  Id: 19508.19324 Suspend: 0 Teb: 7ef74000 Unfrozen
20  Id: 19508.19a78 Suspend: 0 Teb: 7ef71000 Unfrozen
21  Id: 19508.19ad4 Suspend: 0 Teb: 7ef6d000 Unfrozen
22  Id: 19508.19834 Suspend: 0 Teb: 7ef6a000 Unfrozen
23  Id: 19508.19754 Suspend: 0 Teb: 7ef67000 Unfrozen
24  Id: 19508.19aa0 Suspend: 0 Teb: 7ef64000 Unfrozen
25  Id: 19508.19bd0 Suspend: 0 Teb: 7ef61000 Unfrozen
26  Id: 19508.19384 Suspend: 0 Teb: 7ef5d000 Unfrozen
27  Id: 19508.1734c Suspend: 0 Teb: 7ef5a000 Unfrozen
28  Id: 19508.19148 Suspend: 0 Teb: 7ef57000 Unfrozen
29  Id: 19508.19b74 Suspend: 0 Teb: 7ef54000 Unfrozen
30  Id: 19508.18290 Suspend: 0 Teb: 7ef51000 Unfrozen
31  Id: 19508.19a4c Suspend: 0 Teb: 7ef4d000 Unfrozen
32  Id: 19508.19bc0 Suspend: 0 Teb: 7ef4a000 Unfrozen
33  Id: 19508.18bf0 Suspend: 0 Teb: 7ef47000 Unfrozen
34  Id: 19508.1895c Suspend: 0 Teb: 7ef44000 Unfrozen
35  Id: 19508.19314 Suspend: 0 Teb: 7ef41000 Unfrozen
36  Id: 19508.19934 Suspend: 0 Teb: 7ef3a000 Unfrozen
37  Id: 19508.197b0 Suspend: 0 Teb: 7ef31000 Unfrozen
38  Id: 19508.1962c Suspend: 0 Teb: 7ef2d000 Unfrozen
39  Id: 19508.191e0 Suspend: 0 Teb: 7ef2a000 Unfrozen
40  Id: 19508.19438 Suspend: 0 Teb: 7ef27000 Unfrozen
41  Id: 19508.197e8 Suspend: 0 Teb: 7ef24000 Unfrozen
42  Id: 19508.18c38 Suspend: 0 Teb: 7ef21000 Unfrozen
43  Id: 19508.197b4 Suspend: 0 Teb: 7ef1d000 Unfrozen
44  Id: 19508.1978c Suspend: 0 Teb: 7ef1a000 Unfrozen
45  Id: 19508.19b84 Suspend: 0 Teb: 7ef17000 Unfrozen
46  Id: 19508.197a8 Suspend: 0 Teb: 7ef14000 Unfrozen
47  Id: 19508.19660 Suspend: 0 Teb: 7ef3d000 Unfrozen
48  Id: 19508.18574 Suspend: 0 Teb: 7efad000 Unfrozen
49  Id: 19508.17a04 Suspend: 0 Teb: 7efaa000 Unfrozen

We see a correct result if we specify a different structure:

0:000:x86> dt CRITICAL_SECTION 010d97c0
+0x000 DebugInfo        : 0x00862680 _RTL_CRITICAL_SECTION_DEBUG
+0x004 LockCount        : 0n-6
+0x008 RecursionCount   : 0n1
+0×00c OwningThread     : 0×000193bc Void
+0×010 LockSemaphore    : 0×00000a94 Void
+0×014 SpinCount        : 0

This is because the structure definition is from a 32-bit module:

0:000:x86> dt ModuleA!CRITICAL_SECTION
+0x000 DebugInfo        : Ptr32 _RTL_CRITICAL_SECTION_DEBUG
+0x004 LockCount        : Int4B
+0x008 RecursionCount   : Int4B
+0×00c OwningThread     : Ptr32 Void
+0×010 LockSemaphore    : Ptr32 Void
+0×014 SpinCount        : Uint4B

However, the structure we used first is from 64-bit module and has a different offset and size for OwningThread field:

0:000:x86> dt ntdll!_RTL_CRITICAL_SECTION
+0x000 DebugInfo        : Ptr64 _RTL_CRITICAL_SECTION_DEBUG
+0x008 LockCount        : Int4B
+0x00c RecursionCount   : Int4B
+0×010 OwningThread     : Ptr64 Void
+0×018 LockSemaphore    : Ptr64 Void
+0×020 SpinCount        : Uint8B

Because a different 32-bit ntdll module is also loaded we can use it for explicit symbol qualification:

0:000:x86> dt ntdll_774b0000!_RTL_CRITICAL_SECTION
+0×000 DebugInfo        : Ptr32 _RTL_CRITICAL_SECTION_DEBUG
+0×004 LockCount        : Int4B
+0×008 RecursionCount   : Int4B
+0×00c OwningThread     : Ptr32 Void
+0×010 LockSemaphore    : Ptr32 Void
+0×014 SpinCount        : Uint4B

- Dmitry Vostokov @ + -

Trace Analysis Patterns (Part 67)

Wednesday, March 20th, 2013

Sometimes we have insufficiently detailed problem description and/or there are several similar parallel user activities going on simultaneously, for example, several session are launched in a terminal services environment. In such cases when tracing is done for the duration of specific user activity Dominant Event Sequence pattern may help. Here we select the most full sequence of events or event sequence based on some Basic Facts. For example, if session id was missing in problem description we can choose the most long and full process launch seqence and assume that its session id was the one missing:

- Dmitry Vostokov @ + -

Happy St. Patrick’s Screen

Sunday, March 17th, 2013

- Dmitry Vostokov @ + -

Trace Analysis Patterns (Part 66)

Saturday, March 16th, 2013

Suppose we form an adjoint thread based on some message or operation type or some other attribute:

But we do not know where to start to look backwards for any anomalies relevant to our problem:

We go back to our full trace and find a problem message:

Although it is not in our adjoint thread we formed previously it is still considered as Pivot Message helping us to go backwards there:

- Dmitry Vostokov @ + -

Trace Analysis Patterns (Part 65)

Thursday, March 14th, 2013

If Implementation Discourse focuses on objective technology specific discourse then Traces of Individuality pattern focuses on subjective elements in a software log and its messages. Here we mean some specific naming or tracing conventions either from an individual engineer habit or from some corporate coding standard. As an example of it consider a trace message from a catch statement:

"Surprise, surprise, should have never been caught"

More examples for this pattern will be added later.

- Dmitry Vostokov @ + -

Bugtation No.163

Thursday, March 14th, 2013

… what an ideal engineer should be in the eyes of his contemporaries: […] a man of hardware and a child of software.

Amir Alexander, From Voyagers to Martyrs

- Dmitry Vostokov @ + -

WinDbg shortcuts: !sw and !k

Sunday, March 10th, 2013

There is an extension shortcut to the usual WinDbg command .effmach for 64-bit memory dumps of 32-bit processes:

0:000> .load wow64exts

0:000> !sw

Switched to 32bit mode

0:000:x86> !sw

Switched to 64bit mode

Also !k command will display both thread stacks (32-bit and 64-bit):

0:000> !k
Walking 64bit Stack...
Child-SP          RetAddr           Call Site
00000000`0016e018 00000000`74f9aea8 wow64win!NtUserGetMessage+0xa
00000000`0016e020 00000000`74fecf87 wow64win!whNtUserGetMessage+0x30
00000000`0016e080 00000000`74f72776 wow64!Wow64SystemServiceEx+0xd7
00000000`0016e940 00000000`74fed07e wow64cpu!ServiceNoTurbo+0x2d
00000000`0016ea00 00000000`74fec549 wow64!RunCpuSimulation+0xa
00000000`0016ea50 00000000`77c54956 wow64!Wow64LdrpInitialize+0x429
00000000`0016efa0 00000000`77c51a17 ntdll!LdrpInitializeProcess+0x17e4
00000000`0016f490 00000000`77c3c32e ntdll! ?? ::FNODOBFM::`string'+0x29220
00000000`0016f500 00000000`00000000 ntdll!LdrInitializeThunk+0xe
Walking 32bit Stack...
ChildEBP RetAddr
002cf6a0 76ba790d user32!NtUserGetMessage+0x15
002cf6bc 0048148a user32!GetMessageW+0x33
002cf6fc 004816ec notepad!WinMain+0xe6
002cf78c 755533aa notepad!_initterm_e+0x1a1
002cf798 77e29ef2 kernel32!BaseThreadInitThunk+0xe
002cf7d8 77e29ec5 ntdll_77df0000!__RtlUserThreadStart+0x70
002cf7f0 00000000 ntdll_77df0000!_RtlUserThreadStart+0x1b

However, I don’t recommend its usage in iterative scripts because if something goes wrong at one iteration then all subsequent !sw commands will trigger the wrong machine mode but explicit .effmach will set the correct one.

- Dmitry Vostokov @ + -