Software Diagnostics Library

Sometimes we need to check under what security principal or group we run a process or what privileges it has or whether it has impersonating threads. We call this pattern Deviant Token when we find, for example, an unexpected token with a different security identifier, for example, Network Service instead of Local System (SID: S-1-5-18):

PROCESS 8f218d88  SessionId: 0  Cid: 09c4    Peb: 7ffdf000  ParentCid: 0240
DirBase: bffd4260  ObjectTable: e10eae90  HandleCount:  93.
Image: ServiceA.exe
VadRoot 8f1f70e8 Vads 141 Clone 0 Private 477. Modified 2. Locked 0.
DeviceMap e10038d8
Token                             e10ff5d8
[…]

0: kd> !token e10ff5d8
_TOKEN e10ff5d8
TS Session ID: 0
User: S-1-5-20
[…]

Well-known SIDs can be found in this MS article: http://support.microsoft.com/kb/243330

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

Here we provide a definition of malware that highlights the importance of structural and behavioral patterns:

Malware: software that uses planned alteration of structure and behaviour of software to serve malicious purposes.

Notice the recursive character of that definition that includes self-modifying malware and also rootkits where a malicious purpose is to conceal.

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

As was announced earlier we start cataloguing elemental malware detection and analysis patterns. We skip Part 1 because we assign Deviant Module to it. Part 2 deals with Fake Module pattern where one of loaded modules masquerades as a legitimate system DLL or a widely known value adding DLL from some popular 3rd party product. To illustrate this pattern we modeled it as Victimware: a process crashed after loading a malware module:

0:000> k
*** Stack trace for last set context - .thread/.cxr resets it
Child-SP          RetAddr           Call Site
00000000`0026f978 00000001`3f89103a 0x0
00000000`0026f980 00000001`3f8911c4 FakeModule!wmain+0x3a
00000000`0026f9c0 00000000`76e3652d FakeModule!__tmainCRTStartup+0x144
00000000`0026fa00 00000000`7752c521 kernel32!BaseThreadInitThunk+0xd
00000000`0026fa30 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

When we inspect loaded modules we don’t find anything suspicious:

0:000> lmp
start             end                 module name
00000000`76e20000 00000000`76f3f000   kernel32 <none>
00000000`77500000 00000000`776a9000   ntdll    <none>
00000001`3f890000 00000001`3f8a6000   FakeModule <none>
000007fe`f8cb0000 000007fe`f8cc7000   winspool <none>
000007fe`fdb30000 000007fe`fdb9c000   KERNELBASE <none>

However, when checking modules images for any modifications we find that winspool was not compared with existing binary from Microsoft symbol server:

0:000> !for_each_module "!chkimg -v -d @#ModuleName"
Searching for module with expression: kernel32
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: C:\WSDK8\Debuggers\x64\sym\kernel32.dll\503285C111f000\kernel32.dll
No range specified

Scanning section:    .text
Size: 633485
Range to scan: 76e21000-76ebba8d
Total bytes compared: 633485(100%)
Number of errors: 0
0 errors : kernel32
Searching for module with expression: ntdll
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: C:\WSDK8\Debuggers\x64\sym\ntdll.dll\4EC4AA8E1a9000\ntdll.dll
No range specified

Scanning section:    .text
Size: 1049210
Range to scan: 77501000-7760127a
Total bytes compared: 1049210(100%)
Number of errors: 0

Scanning section:       RT
Size: 474
Range to scan: 77602000-776021da
Total bytes compared: 474(100%)
Number of errors: 0
0 errors : ntdll
Searching for module with expression: FakeModule
Error for FakeModule: Could not find image file for the module. Make sure binaries are included in the symbol path.
Searching for module with expression: winspool
Error for winspool: Could not find image file for the module. Make sure binaries are included in the symbol path.
Searching for module with expression: KERNELBASE
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: C:\WSDK8\Debuggers\x64\sym\KERNELBASE.dll\503285C26c000\KERNELBASE.dll
No range specified

Scanning section:    .text
Size: 302047
Range to scan: 7fefdb31000-7fefdb7abdf
Total bytes compared: 302047(100%)
Number of errors: 0
0 errors : KERNELBASE

Checking module data reveals that it was loaded not from System32 folder and doesn’t have any version information:

0:000> lmv m winspool
start             end                 module name
000007fe`f8cb0000 000007fe`f8cc7000   winspool   (deferred)
Image path: C:\Work\AWMA\FakeModule\x64\Release\winspool.drv
Image name: winspool.drv
Timestamp:        Fri Dec 28 22:22:42 2012 (50DE1BB2)
CheckSum:         00000000
ImageSize:        00017000
File version:     0.0.0.0
Product version:  0.0.0.0
File flags:       0 (Mask 0)
File OS:          0 Unknown Base
File type:        0.0 Unknown
File date:        00000000.00000000
Translations:     0000.04b0 0000.04e4 0409.04b0 0409.04e4

We could see that path from running this command as well :

0:000> !for_each_module
00: 0000000076e20000  0000000076f3f000         kernel32 C:\Windows\System32\kernel32.dll                      kernel32.dll
01: 0000000077500000  00000000776a9000            ntdll C:\Windows\System32\ntdll.dll                            ntdll.dll
02: 000000013f890000  000000013f8a6000       FakeModule C:\Work\AWMA\FakeModule\x64\Release\FakeModule.exe  FakeModule.exe
03: 000007fef8cb0000  000007fef8cc7000         winspool C:\Work\AWMA\FakeModule\x64\Release\winspool.drv
04: 000007fefdb30000  000007fefdb9c000       KERNELBASE C:\Windows\System32\KERNELBASE.dll                  KERNELBASE.dll

or from PEB:

0:000> !peb
PEB at 000007fffffdf000
[...]
7fef8cb0000 50de1bb2 Dec 28 22:22:42 2012 C:\Work\AWMA\FakeModule\x64\Release\winspool.drv
[…]

Another sign is module size in memory which is much smaller than real winspool.drv:

0:000> ? 000007fe`f8cc7000 - 000007fe`f8cb0000
Evaluate expression: 94208 = 00000000`0001700

Module size can help if legitimate module from well-known folder was replaced. Module debug directory and the size of export and import directories are also different with the former revealing the development folder:

0:000> !dh 000007fe`f8cb0000
[...]
   0 [       0] address [size] of Export Directory
[…]
9000 [     208] address [size] of Import Address Table Directory
[…]
Debug Directories(2)
Type       Size     Address  Pointer
cv           49        e2c0     cac0 Format: RSDS, guid, 1, C:\Work\AWMA\FakeModule\x64\Release\winspool.pdb

This can also be seen from the output of !lmi command:

0:000> !lmi 7fef8cb0000
Loaded Module Info: [7fef8cb0000]
Module: winspool
Base Address: 000007fef8cb0000
Image Name: winspool.drv
Machine Type: 34404 (X64)
Time Stamp: 50de1bb2 Fri Dec 28 22:22:42 2012
Size: 17000
CheckSum: 0
Characteristics: 2022
Debug Data Dirs: Type  Size     VA  Pointer
CODEVIEW    49,  e2c0,    cac0 RSDS - GUID: {29D85193-1C9D-4997-95BA-DD190FA3C1BF}
Age: 1, Pdb: C:\Work\AWMA\FakeModule\x64\Release\winspool.pdb
??    10,  e30c,    cb0c [Data not mapped]
Symbol Type: DEFERRED - No error - symbol load deferred
Load Report: no symbols loaded

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

In addition to stack trace collection we often are interested in Module Collection (we called this pattern initially Vendor Collection), especially if we would like to check if some vendor DLL is present in some process address space in a complete memory dump (kernel module list or module list from a process memory dump is trivial). Or we need to check for some vendor information from problem description (lmv command). If we have a complete memory dump from x64 system then listing modules for each process is not enough. For example, we might have this:

0: kd> lmu
start             end                 module name
00000000`00ab0000 00000000`00ae8000   AppA    (deferred)
00000000`74fe0000 00000000`7502e000   wow64win   (deferred)
00000000`75030000 00000000`75075000   wow64      (deferred)
00000000`750c0000 00000000`750c9000   wow64cpu   (deferred)
00000000`77b70000 00000000`77cf7000   ntdll      (pdb symbols)

AppA is a 32-bit process and has an additional 32-bit module list that is more useful. We can set x86 context for a thread from that process and get the list of 32-bit modules:

0: kd> .load wow64exts

0: kd> .thread /w fffffa800e372060
Implicit thread is now fffffa80`0e372060
x86 context set

0: kd:x86> .reload
Loading Kernel Symbols
Loading User Symbols
Loading unloaded module list
Loading Wow64 Symbols

0: kd:x86> lmu
start             end                 module name
00000000`00ab0000 00000000`00ae8000   AppA    (deferred)
00000000`73490000 00000000`73515000   COMCTL32   (deferred)
00000000`73520000 00000000`735c3000   MSVCR90    (deferred)
00000000`735d0000 00000000`7365e000   MSVCP90    (deferred)
00000000`74920000 00000000`7493e000   USERENV    (deferred)
00000000`74940000 00000000`74ade000   comctl32_74940000   (deferred)
00000000`74af0000 00000000`74b02000   MSASN1     (deferred)
00000000`74b10000 00000000`74c03000   CRYPT32    (deferred)
00000000`74dc0000 00000000`74e5b000   MSVCR80    (deferred)
00000000`74f60000 00000000`74fd6000   NETAPI32   (deferred)
00000000`74fe0000 00000000`7502e000   wow64win   (deferred)
00000000`75030000 00000000`75075000   wow64      (deferred)
00000000`750b0000 00000000`750ba000   WTSAPI32   (deferred)
00000000`750c0000 00000000`750c9000   wow64cpu   (deferred)
00000000`75cf0000 00000000`75d50000   Secur32    (deferred)
00000000`75d50000 00000000`76861000   SHELL32    (deferred)
00000000`76a10000 00000000`76aa0000   GDI32      (deferred)
00000000`76b30000 00000000`76b90000   IMM32      (deferred)
00000000`76be0000 00000000`76cf0000   kernel32   (deferred)
00000000`76e30000 00000000`76f75000   ole32      (deferred)
00000000`76f80000 00000000`7702a000   msvcrt     (deferred)
00000000`77030000 00000000`77037000   PSAPI      (deferred)
00000000`77040000 00000000`77110000   USER32     (deferred)
00000000`77110000 00000000`77169000   SHLWAPI    (deferred)
00000000`77170000 00000000`771ed000   USP10      (deferred)
00000000`77380000 00000000`7740d000   OLEAUT32   (deferred)
00000000`77640000 00000000`77649000   LPK        (deferred)
00000000`776e0000 00000000`777d0000   RPCRT4     (deferred)
00000000`777d0000 00000000`77898000   MSCTF      (deferred)
00000000`778a0000 00000000`77966000   ADVAPI32   (deferred)
00000000`77b70000 00000000`77cf7000   ntdll      (pdb symbols)
00000000`77d30000 00000000`77e90000   ntdll_77d30000 # (pdb symbols)

So it looks like we need to dump modules for each thread. However, the output would be enormous unless we skip threads having the same PID. After some tinkering I wrote this WinDbg script with moderate output volume:

.load wow64exts
!for_each_thread ".thread @#Thread; .if (@$t0 != @@c++(@$thread->Cid.UniqueProcess)) {.reload /user;lmvu;.thread /w @#Thread;.reload /user;lmvu;r $t0 = @@c++(@$thread->Cid.UniqueProcess);.effmach AMD64; }"

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

Although a handle leak may lead to Insufficient Memory it is not always the case especially if pool structures are small such as events. So we describe another pattern called Handle Leak that covers high memory usage (including fat structures), high handle counts and also abnormal differences in allocations and deallocations. As an example for the latter here is a nonpaged pool leak of Event objects and correlated pooltag ABCD. Although memory usage footprint is small compared with other nonleaking pooltags we see the difference between Allocs and Frees is surely abnormal correlating with high handle counts:

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

Pool Used:
NonPaged                    Paged
Tag    Allocs    Frees     Diff     Used   Allocs    Frees     Diff     Used
[…]
ABCD  1778517  1704538    73979  4734656        0        0        0        0 UNKNOWN pooltag ‘ABCD’, please update pooltag.txt
Even  6129633  6063728    65905  4224528        0        0        0        0 Event objects
[…]

0: kd> !process 0 0

[...]

PROCESS d2b85360  SessionId: 2  Cid: 1bf4    Peb: 7ffdf000  ParentCid: 1688
DirBase: 7d778dc0  ObjectTable: e53dda08  HandleCount: 18539.
Image: AppA.exe

PROCESS b2fcd670  SessionId: 2  Cid: 0818    Peb: 7ffd4000  ParentCid: 1688
DirBase: 7d778400  ObjectTable: b3ffd8c0  HandleCount: 36252.
Image: AppB.exe

[...]

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

Critical Stack Trace pattern addresses abnormal behaviour such as page fault processing or any other critical system activity that is waiting too long. Such activity is either finishes quickly or lead to normal bugcheck processing code. For example, this thread is stuck in page fault processing for 32 minutes while loading a resource:

THREAD fffffa80f0603c00  Cid 376.3d6  Teb: 000007fffffd6000 Win32Thread: fffff900c09e0640 WAIT: (Executive) KernelMode Non-Alertable
[...]
Wait Start TickCount      6281298        Ticks: 123391 (0:00:32:04.102)
[…]
Child-SP          RetAddr           Call Site
fffff880`3fc99030 fffff800`01882bd2 nt!KiSwapContext+0×7a
fffff880`3fc99170 fffff800`01893f8f nt!KiCommitThreadWait+0×1d2
fffff880`3fc99200 fffff880`016283ff nt!KeWaitForSingleObject+0×19f
fffff880`3fc992a0 fffff880`01620fc6 Ntfs!NtfsNonCachedIo+0×23f
fffff880`3fc99470 fffff880`01622a68 Ntfs!NtfsCommonRead+0×7a6
fffff880`3fc99610 fffff880`00fb4bcf Ntfs!NtfsFsdRead+0×1b8
fffff880`3fc99820 fffff880`00fb36df fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0×24f
fffff880`3fc998b0 fffff800`018b44f5 fltmgr!FltpDispatch+0xcf
fffff880`3fc999a0 fffff800`018b3fc9 nt!IoPageRead+0×255
fffff880`3fc99a30 fffff800`0189a85a nt!MiIssueHardFault+0×255
fffff880`3fc99ac0 fffff800`0188b2ee nt!MmAccessFault+0×146a
fffff880`3fc99c20 00000000`779da643 nt!KiPageFault+0×16e (TrapFrame @ fffff880`3fd99c20)
00000000`039ff4f0 00000000`779d8b1e ntdll!LdrpGetRcConfig+0xcd
00000000`039ff580 00000000`779da222 ntdll!LdrIsResItemExist+0×1e
00000000`039ff5c0 00000000`779f82c4 ntdll!LdrpSearchResourceSection_U+0xa4
00000000`039ff6e0 000007fe`fe0075c1 ntdll!LdrFindResource_U+0×44
00000000`039ff720 000007fe`fb217777 KERNELBASE!FindResourceExW+0×85
[…]

The Top Blocking Module is NTFS so we might want then to look for other similar stack traces from stack trace collection.

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

As there was no shape for a pint in Visio I resorted to a message box for the occasion.

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

Here are some achievements I’d like to highlight for 2012 (The Year of Software Trace Analysis):

• The birth of Software Diagnostics as a discipline
• Pattern-driven software diagnostics comes to Mac OS X
• Pattern-driven software trace and log analysis acquires a reference training course
• Software Narratology gets an introduction
• Victimware is introduced

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

This pattern is called Opposition Messages (borrowed from binary opposition originated in Saussure’s structuralism). It covers the following pairs of messages usually found in software traces and logs such as:

• open / close
• create / destroy
• allocate / free (deallocate)
• call / return
• enter / exit (leave)
• load / unload
• save / load
• lock / unlock
• map / unmap

The absence of an opposite may point to some problems such as synchronization and leaks or Incomplete History (wait chains). There can always be a possibility that a second term is missing due to Sparse Trace but this is a poor implementation choice that leads to confusion during troubleshooting and debugging.

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

Some tracing tools such as Citrix CDFControl have an option to split software traces and logs into several files during long recording. Although this should be done judiciously it is really necessary sometimes. We call this pattern Split Trace. What to do if we get several trace files and we want to use some other analysis tool such as Citrix CDFAnalyzer? If we know that the problem happened just before the tracing was stopped we can look at the last few such files from the file sequence (although we recommend a circular trace here). Otherwise we can convert them into CVS files and import into Excel which also supports adjoint threading.

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

To celebrate the last unique occurrence of 12.12.12 in this Century I created a Computical Art (Computicart) picture that uses minimalist software trace analysis diagrams I use for trace and log analysis patterns made even better for Accelerated Windows Software Trace Analysis course. The following diagram symbolizes several patterns. Suppose we trace personal or world events each year and form an Adjoint Thread with messages having DD=MM=YY timestamp invariant (or filter them). Then we clearly see a Discontinuity before the next Century with much bigger Time Delta than between such messages. Also these messages form a Periodic Message Block in relation to the full trace.

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

We have decided to factor out Anchor Messages example of message interleave into another pattern called Message Interleave. It covers superposition of different anchor messages, for example, process launch and exit, or DLL load and unload:

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

Whereas, when naturally visualized with Dump2Picture, a CDF trace looks like a sea with embedded library, a process monitor log looks more like a fragment from a memory dump with some large scale internal structure:

Its 450×1280 slice:

Top and bottom of x4 magnified image:

…

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

Sometimes we don’t see anything in the trace or see very little because particular source code fragment was not covered by trace statements (see also PLOTs):

We call this pattern Sparse Trace and this is different from Missing Component pattern where some modules were not included for tracing explicitly although there is tracing code there or Visibility Limit pattern where tracing is intrinsically impossible. Often technical support and escalation engineers request to add more trace statements and software engineers extend tracing coverage iteratively as needed.

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