Archive for March, 2008

CDF Traces: Analyzing Process Launch Sequence

Monday, March 31st, 2008

Citrix CDF traces are based on ETW (Event Tracing for Windows) and therefore Citrix customers, their support personnel and developers can use MS TraceView tool for troubleshooting Citrix terminal service environments:

Viewing Common Diagnostics Facility (CDF) Traces Using TraceView

In cases with slow logon or slow process startup we can analyze process launch sequence to determine delays. In the output trace we can filter tzhook module messages which also contain session id (this is quite handy to differentiate between different sessions), for example: 

PID      TID      TIME          MESSAGE     
21864    21912    06:34:53.598  tzhook: Attach on process - cmd.exe session=51         
21620    20372    06:34:59.754  tzhook: Attach on process - acregl.exe session=51         
18668    21240    06:35:02.704  tzhook: Attach on process - cmstart.exe session=51         
18560    18832    06:35:02.735  tzhook: Attach on process - wfshell.exe session=51         
18204    20060    06:35:06.575  tzhook: Attach on process - icast.exe session=51         
20640    21104    06:35:07.717  tzhook: Attach on process - LOGON.EXE session=51         
21188    21032    06:35:07.938  tzhook: Attach on process - cscript.exe session=51         
21888    19592    06:35:11.157  tzhook: Attach on process - WScript.exe session=51         
20600    20732    06:35:11.780  tzhook: Attach on process - admin.exe session=51         
17976    20456    06:35:18.752  tzhook: Attach on process - winlogon.exe session=53         
21332    13156    06:35:51.625  tzhook: Attach on process - mpnotify.exe session=53         
10988    10732    06:35:57.043  tzhook: Attach on process - rundll32.exe session=53

Here is another process launch sequence for published Notepad application:

PID     TID     TIME            MESSAGE
15828   18720   15:34:02.637    tzhook: Attach on process - winlogon.exe session=2 
5300    18508   15:34:03.043    tzhook: Attach on process - mpnotify.exe session=2 
17948   19300   15:34:03.356    tzhook: Attach on process - userinit.exe session=2 
17956   19316   15:34:03.415    tzhook: Attach on process - cmd.exe session=2 
5384    5324    15:34:03.443    tzhook: Attach on process - cmd.exe session=2 
19432   19264   15:34:03.461    tzhook: Attach on process - SSONSVR.EXE session=2 
12480   7472    15:34:03.466    tzhook: Attach on process - cmd.exe session=2 
19448   19364   15:34:03.474    tzhook: Attach on process - net.exe session=2 
19416   19656   15:34:03.489    tzhook: Attach on process - acregl.exe session=2 
19480   19596   15:34:03.544    tzhook: Attach on process - cmstart.exe session=2 
664     19512   15:34:03.559    tzhook: Attach on process - wfshell.exe session=2 
19904   13140   15:34:03.610    tzhook: Attach on process - net.exe session=2 
6864    20036   15:34:03.746    tzhook: Attach on process - icast.exe session=2 
19540   20016   15:34:03.749    tzhook: Attach on process - ctfmon.exe session=2 
19944   19032   15:34:03.757    tzhook: Attach on process - net.exe session=2 
10232   18356   15:34:03.787    tzhook: Attach on process - notepad.exe session=2

Such sequences are also useful to determine a process upon which the session initialization or startup sequence hangs. In this case a user dump of that process might be useful.

Of course we can do all this with Process Monitor and other similar tools but here we get other Citrix related trace messages as well. All in one.

- Dmitry Vostokov @ DumpAnalysis.org -

LiterateScientist and ManagementBits update (March, 2008)

Monday, March 31st, 2008

I was very busy this month with the forthcoming Memory Dump Analysis Anthology Volume 1 plus I had a business trip to Redmond and therefore I really didn’t have enough time to contribute well to other my blogs. Nevertheless I finished reading Incompleteness book during my transatlantic flights, started reading two others and here is the small update:

LiterateScientist Blog:

Incompleteness: The Proof and Paradox of Kurt Godel

The Philosophers Toolkit

ManagementBits Blog:

The Science of Career Promotions

Management Bit and Tip 0×200

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Forum has been reopened!

Sunday, March 30th, 2008

This is an attempt to revive the forum closed a year ago due to the lack of interest during that time. Now the number of visitors has increased by an order of magnitude and I get more and more requests to help with crash dump analysis but I cannot guarantee immediate response. Therefore I upgraded and reopened Crash Dump Analysis and Debugging Forum and encourage using it. In order to prevent spammers gaining access any new registration has to be approved by me (usually in less than 24 hours).

- Dmitry Vostokov @ DumpAnalysis.org -

AW Reprints Device Drivers Book

Saturday, March 29th, 2008

Just noticed that this month Addison-Wesley Professional reprints in paperback its out of stock hardcover book originally published in 1999:

Developing Windows NT Device Drivers: A Programmer’s Handbook (paperback)

Buy from Amazon

Highly recommended. Almost all book material is still relevant today even in the light of new WDF model. Please also see my post Moving to kernel space (updated references).

- Dmitry Vostokov @ DumpAnalysis.org -

Complete Dump: User Space Critical Sections

Friday, March 28th, 2008

Just a short note. Suppose we have a complete memory dump and we want to check critical sections to see any anomalies. We can do this by using !for_each_process extension command:

0: kd> !for_each_process ".process /r /p @#Process; !ntsdexts.locks"
Implicit process is now a59a4648
Loading User Symbols

NTSDEXTS: Unable to resolve ntdll!RtlCriticalSectionList
NTSDEXTS: Please check your symbols
Implicit process is now a553cd88
Loading User Symbols
....

Scanned 11 critical sections
Implicit process is now a518b1b0
Loading User Symbols
....

Scanned 105 critical sections
Implicit process is now a513a348
Loading User Symbols
....

Scanned 977 critical sections
Implicit process is now a5659d88
Loading User Symbols
....

Scanned 438 critical sections
Implicit process is now a551abb8
Loading User Symbols
....
...
...
...
...

Here the first NTSDEXTS warning is normal because we don’t have user space for System process.

- Dmitry Vostokov @ DumpAnalysis.org -

The Hunt for the Debugger

Friday, March 28th, 2008

Sometimes we have processes that actively monitor debugger attachments to prevent reverse engineering and terminate themselves if such attempts are detected. Some of them use very simple methods to achieve this like creating a thread that periodically calls IsDebuggerPresent API or waits for debugger events. In such cases attempts of any application to actively attach to these processes result in their termination.

Consider the following stack trace from the postmortem crash dump saved by NTSD on Windows Server 2003:

0:000> kL
ChildEBP RetAddr 
00fefbcc 098b84a1 kernel32!RaiseException+0x53
...
...
...
00fefd28 0116a86a component!_CRT_INIT+0x187
00fefd6c 0116a8e6 component!__DllMainCRTStartup+0xb7
00fefd74 7c81a352 component!_DllMainCRTStartup+0x1d
00fefd94 7c830e70 ntdll!LdrpCallInitRoutine+0x14
00fefe4c 77e668a3 ntdll!LdrShutdownProcess+0x182
00feff38 77e66905 kernel32!_ExitProcess+0x43
00feff4c 00561ab9 kernel32!ExitProcess+0x14
00feffb8 77e64829 application!foo+0x41
00feffec 00000000 kernel32!BaseThreadStart+0x34

Disassembling application!foo shows the call to WaitForDebugEvent API:

0:000> u application!foo
application!foo:
00561a78 push    ebp
00561a79 mov     ebp,esp
00561a7b sub     esp,60h
00561a7e push    0FFFFFFFFh
00561a80 lea     eax,[ebp-60h]
00561a83 push    eax
00561a84 call    dword ptr [application!_imp__WaitForDebugEvent (00655224)]
00561a8a mov     eax,dword ptr [ebp+8]

We also see it on the raw stack which might also help in more complex cases:

0:000> !teb
TEB at 7ffdd000
    ExceptionList:        00fefbf8
    StackBase:            00ff0000
    StackLimit:           00fef000
    SubSystemTib:         00000000
    FiberData:            00001e00
    ArbitraryUserPointer: 00000000
    Self:                 7ffdd000
    EnvironmentPointer:   00000000
    ClientId:             000063fc . 00003270
    RpcHandle:            00000000
    Tls Storage:          00000000
    PEB Address:          7ffdb000
    LastErrorValue:       0
    LastStatusValue:      c0000034
    Count Owned Locks:    0
    HardErrorMode:        0

0:000> dds 00fef000 00ff0000
...
...
...
00fefecc  00000000
00fefed0  00feff48
00fefed4  77e9c4d7 kernel32!WaitForDebugEvent+0×66
00fefed8  c0000008
00fefedc  00000000
00fefee0  77e41ef3 kernel32!SleepEx+0×91
00fefee4  00000000
00fefee8  00000000


How would we find what process was trying to attach to our application? Let’s go with pure crash dump analysis approach. We can take the advantage of RaiseException call and get a kernel or a complete memory dump to examine all running processes and their threads. In order to model this I created a small program that simulates the behavior shown above:

// IsDebuggerPresent64 

#include "stdafx.h"
#include "windows.h"

int _tmain(int argc, _TCHAR* argv[])
{
    while (1)
    {
        IsDebuggerPresent()
            ? puts ("Yes"),
                RaiseException(0x12345678,
                    0, 0, NULL)
            : puts ("No");
        Sleep(5000);
    }

    return 0;
}

Then I configured Process Monitoring Rules in Userdump Process Dumper Control Panel applet to bugcheck the system after dumping:

 

Then I asked one of my friends to debug the running instance of that application and let me know if there was any sudden BSOD. Indeed there was one and I got my complete memory dump (although kernel dump would suffice here). Let’s look at it.

We see that our process has an open debug port and its main thread is suspended:

kd> !process /r /p fffffadfe73f9c20
PROCESS fffffadfe73f9c20
    SessionId: 0  Cid: 0e4c    Peb: 7fffffd4000  ParentCid: 0e54
    DirBase: 2c472000  ObjectTable: fffffa80006f1690  HandleCount:  12.
    Image: IsDebuggerPresent64.exe
    VadRoot fffffadfe6ef3e30 Vads 26 Clone 0 Private 97. Modified 0. Locked 0.
    DeviceMap fffffa8000930540
    Token                             fffffa80030e7910
    ElapsedTime                       00:00:03.062
    UserTime                          00:00:00.000
    KernelTime                        00:00:00.000
    QuotaPoolUsage[PagedPool]         16288
    QuotaPoolUsage[NonPagedPool]      3488
    Working Set Sizes (now,min,max)  (1322, 50, 345) (5288KB, 200KB, 1380KB)
    PeakWorkingSetSize                1322
    VirtualSize                       7 Mb
    PeakVirtualSize                   7 Mb
    PageFaultCount                    1314
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      107
    DebugPort                         fffffadfe6ec9040

THREAD fffffadfe69a2bf0  Cid 0e4c.0e74  Teb: 000007fffffde000 Win32Thread: 0000000000000000 WAIT: (Unknown) KernelMode Non-Alertable
SuspendCount 1
    fffffadfe69a2e90  Semaphore Limit 0×2
Not impersonating
DeviceMap                 fffffa8000930540
Owning Process            fffffadfe73f9c20       Image:         IsDebuggerPresent64.exe
Wait Start TickCount      37247          Ticks: 49 (0:00:00:00.765)
Context Switch Count      45            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address IsDebuggerPresent64 (0×00000001400013b0)
Start Address kernel32!BaseProcessStart (0×0000000077d59620)
Stack Init fffffadfdf7b5e00 Current fffffadfdf7b54f0
Base fffffadfdf7b6000 Limit fffffadfdf7b0000 Call 0

Priority 12 BasePriority 8 PriorityDecrement 2
Child-SP          RetAddr           Call Site
fffffadf`df7b5530 fffff800`0103b063 nt!KiSwapContext+0x85
fffffadf`df7b56b0 fffff800`0103c403 nt!KiSwapThread+0xc3
fffffadf`df7b56f0 fffff800`0105dc7c nt!KeWaitForSingleObject+0x528
fffffadf`df7b5780 fffff800`0105db2b nt!KiSuspendThread+0x2c
fffffadf`df7b57c0 fffff800`01058e71 nt!KiDeliverApc+0x20a
fffffadf`df7b5840 fffff800`0103c403 nt!KiSwapThread+0xde
fffffadf`df7b5880 fffffadf`dfd4a20c nt!KeWaitForSingleObject+0x528
fffffadf`df7b5910 fffffadf`dfd4a3be userdump!UdpCompleteExceptionForwarding+0x11c
fffffadf`df7b5990 fffffadf`dfd49dd8 userdump!UdpForwardException+0x13e
fffffadf`df7b59c0 fffff800`012ce9cf userdump!UdIoctl+0x618
fffffadf`df7b5a70 fffff800`012df026 nt!IopXxxControlFile+0xa5a
fffffadf`df7b5b90 fffff800`010410fd nt!NtDeviceIoControlFile+0x56
fffffadf`df7b5c00 00000000`77ef0a5a nt!KiSystemServiceCopyEnd+0x3 (TrapFrame @ fffffadf`df7b5c70)

If we search for a process that has NtWaitForDebugEvent function present on one of its stack traces we would find the debugger:

kd> !stacks 2 nt!NtWaitForDebugEvent
...
...
...
                [fffffadfe63da3b0 ntsd.exe]
 e54.000e50  fffffadfe6afbbf0 ffff6e8a Blocked    nt!KiSwapContext+0×85
                nt!KiSwapThread+0xc3
                nt!KeWaitForSingleObject+0×528
                nt!NtWaitForDebugEvent+0×342
                nt!KiSystemServiceCopyEnd+0×3
                ntdll!ZwWaitForDebugEvent+0xa
                dbgeng!LiveUserDebugServices::WaitForEvent+0xee
                dbgeng!LiveUserTargetInfo::WaitForEvent+0×488
                dbgeng!RawWaitForEvent+0×23c
                dbgeng!DebugClient::WaitForEvent+0×96
                ntsd!MainLoop+0xb7
                ntsd!main+0×18e
                ntsd!mainCRTStartup+0×171
                kernel32!BaseProcessStart+0×29

We see that it is NTSD.  

- Dmitry Vostokov @ DumpAnalysis.org -

Ceteris Paribus in Comparative Troubleshooting

Thursday, March 27th, 2008

Ceteris Paribus means “with other things [being] the same” (Latin) and when applied to software troubleshooting and debugging means equal environment and configuration. My favorite example is troubleshooting an issue using two Citrix CDF traces (ETW based): one is for the problem and another for the expected behavior. Say we have a terminal services connectivity problem where a published application doesn’t start on the one particular server in Citrix farm. Here Ceteris Paribus means that the application, connection method, configuration, user name, and so on, are all the same for both traces. 

Looks like I have used Latin to obfuscate something obvious but surely many engineers forget it when facing complex issues. This equally applies to debugging as well. 

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 56)

Thursday, March 27th, 2008

The case when a function pointer or a return address becomes a Wild Pointer and EIP or RIP value lies in a valid region of memory the execution path may continue through a region called Wild Code. This might loop on itself or eventually reach non-executable or invalid pages and produce an exception. Local Buffer Overflow might lead to this behavior and also data corruption that overwrites function pointers with valid memory addresses.

My favorite example is when a function pointer points to zeroed pages with EXECUTE page attribute. What will happen next when we dereference it? All zeroes are perfect x86/x64 code:

0:001> dd 0000000`771afdf0
00000000`771afdf0  00000000 00000000 00000000 00000000
00000000`771afe00  00000000 00000000 00000000 00000000
00000000`771afe10  00000000 00000000 00000000 00000000
00000000`771afe20  00000000 00000000 00000000 00000000
00000000`771afe30  00000000 00000000 00000000 00000000
00000000`771afe40  00000000 00000000 00000000 00000000
00000000`771afe50  00000000 00000000 00000000 00000000
00000000`771afe60  00000000 00000000 00000000 00000000

0:001> u
ntdll!DbgUserBreakPoint:
00000000`771afe00 0000    add     byte ptr [rax],al
00000000`771afe02 0000    add     byte ptr [rax],al
00000000`771afe04 0000    add     byte ptr [rax],al
00000000`771afe06 0000    add     byte ptr [rax],al
00000000`771afe08 0000    add     byte ptr [rax],al
00000000`771afe0a 0000    add     byte ptr [rax],al
00000000`771afe0c 0000    add     byte ptr [rax],al
00000000`771afe0e 0000    add     byte ptr [rax],al

Now if RAX points to a valid memory page with WRITE attribute the code will modify the first byte at that address:

0:001> dq @rax
000007ff`fffdc000 00000000`00000000 00000000`035a0000
000007ff`fffdc010 00000000`0359c000 00000000`00000000
000007ff`fffdc020 00000000`00001e00 00000000`00000000
000007ff`fffdc030 000007ff`fffdc000 00000000`00000000
000007ff`fffdc040 00000000`0000142c 00000000`00001504
000007ff`fffdc050 00000000`00000000 00000000`00000000
000007ff`fffdc060 000007ff`fffd8000 00000000`00000000
000007ff`fffdc070 00000000`00000000 00000000`00000000

Therefore the code will be perfectly executed:

0:001> t
ntdll!DbgBreakPoint+0x2:
00000000`771afdf2 0000    add     byte ptr [rax],al ds:000007ff`fffdc000=00

0:001> t
ntdll!DbgBreakPoint+0x4:
00000000`771afdf4 0000    add     byte ptr [rax],al ds:000007ff`fffdc000=00

0:001> t
ntdll!DbgBreakPoint+0x6:
00000000`771afdf6 0000    add     byte ptr [rax],al ds:000007ff`fffdc000=00

0:001> t
ntdll!DbgBreakPoint+0x8:
00000000`771afdf8 0000    add     byte ptr [rax],al ds:000007ff`fffdc000=00

0:001> t
ntdll!DbgBreakPoint+0xa:
00000000`771afdfa 0000    add     byte ptr [rax],al ds:000007ff`fffdc000=00

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis AntiPatterns (Part 9)

Thursday, March 27th, 2008

Symbolless Analysis is another anti-pattern when an engineer either in a hurry or due to laziness doesn’t apply proper symbols and relies only on timestamps and module/offsets or trusts what WinDbg says and ignores symbol warnings. I usually apply symbols even in obvious cases and in hard ones strive to apply them until all possibilities are exhausted including search using PDBFinder.

Another weak variant is called Imageless Analysis when an engineer doesn’t specify proper Executable Image Search Path when it is necessary perhaps due to ignorance or just plain laziness again. Please see Minidump Analysis example for proper minidump analysis.

- Dmitry Vostokov @ DumpAnalysis.org -

The Time of the Crash

Wednesday, March 26th, 2008

When we have a crash dump WinDbg tells us the time of the crash:

1: kd> vertarget
Windows Vista Kernel Version 6000 MP (2 procs) Free x64
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 6000.16575.amd64fre.vista_gdr.071009-1548
Kernel base = 0xfffff800`01c00000 PsLoadedModuleList = 0xfffff800`01d9af70
Debug session time: Tue Jan 29 11:03:52.572 2008 (GMT+0)
System Uptime: 0 days 0:12:06.648

However I couldn’t find the similar command in GDB documentation. 

One option is to check core file timestamp. For kernel core files perhaps there is some kernel variable we can examine too (I’m interested in FreeBSD here). 

If anyone knows about GDB command that shows the time of a crash or any other method please let me know. Any hints are greatly appreciated!

- Dmitry Vostokov @ DumpAnalysis.org

Crash Dump Analysis Publishing Roadmap

Wednesday, March 26th, 2008

It may appear that I have announced too many titles but they all fall into the well-defined publishing roadmap (excluding a couple of publishing digressions like Debugware book):

This is a high level illustration of global incremental and iterative parts of IIPP (Iterative and Incremental Publishing Process) that I coined some months earlier. More about local iterative and incremental parts in one of my next posts. 

- Dmitry Vostokov @ DumpAnalysis.org -

Advanced Windows® Crash Dump Analysis

Tuesday, March 25th, 2008

This is planned for publication after Windows® Crash Dump Analysis book. Preliminary information is:

  • Title: Advanced Windows® Crash Dump Analysis
  • Paperback: 512 pages (*)
  • ISBN-13: 978-0-9558328-8-8
  • Author: Dmitry Vostokov
  • Publisher: Opentask (01 Dec 2009)
  • Language: English
  • Product Dimensions: 22.86 x 15.24

(*) subject to change

- Dmitry Vostokov @ DumpAnalysis.org -

Windows Internals Experts

Tuesday, March 25th, 2008

Microsoft is looking for 5 Windows Internals SME to help them with their special project. Details can be found on CPR Team blog:

Wanted: Windows Internals subject matter experts

- Dmitry Vostokov @ DumpAnalysis.org -

Memory Dump Analysis Anthology, Volume 2

Tuesday, March 25th, 2008

Although the first volume has not been published yet (scheduled for 15th of April, 2008) the planning for the second volume has already begun. Preliminary information is:

  • Title: Memory Dump Analysis Anthology, Volume 2
  • Paperback: 512 pages (*)
  • ISBN-13: 978-0-9558328-7-1
  • Author: Dmitry Vostokov
  • Publisher: Opentask (01 Oct 2008)
  • Language: English
  • Product Dimensions: 22.86 x 15.24

Hardcover version is also planned. PDF version will be available for download too.

(*) subject to change

- Dmitry Vostokov @ DumpAnalysis.org -

Exploring NDIS Extension

Tuesday, March 25th, 2008

There is a good Microsoft white paper about !ndiskd commands to interrogate kernel dumps:

Debugging NDIS Drivers

Applying !ndiskd.protocols command we can see that there are more protocols added to Vista: 

Windows Server 2003 SP2:

kd> !ndiskd.protocols
 Protocol 862db330: NDISUIO
    Open 86420650 - Miniport: 862e2ab0 AMD PCNET Family PCI Ethernet Adapter

 Protocol 86324780: TCPIP_WANARP
    Open 86324008 - Miniport: 863a2130 WAN Miniport (IP)

 Protocol 86318790: TCPIP
    Open 8637c008 - Miniport: 862e2ab0 AMD PCNET Family PCI Ethernet Adapter

 Protocol 863e3c28: NDPROXY
    Open 8639e0d0 - Miniport: 86361530 Direct Parallel
    Open 8639bb48 - Miniport: 86361530 Direct Parallel
    Open 863e48b0 - Miniport: 863e3130 WAN Miniport (L2TP)
    Open 86404008 - Miniport: 863e3130 WAN Miniport (L2TP)

 Protocol 863a9d80: RASPPPOE

 Protocol 863a9008: NDISWAN
    Open 863e3ab0 - Miniport: 86361530 Direct Parallel
    Open 86398c30 - Miniport: 862c4530 WAN Miniport (PPTP)
    Open 864618f8 - Miniport: 8637a870 WAN Miniport (PPPOE)
    Open 86468a28 - Miniport: 863e3130 WAN Miniport (L2TP)

Vista: 

1: kd> !ndiskd.protocols
 Protocol fffffa8004569580: RSPNDR
    Open fffffa8004566a20 - Miniport: fffffa80039711a0 Broadcom NetXtreme 57xx Gigabit Controller

 Protocol fffffa80043a4900: LLTDIO
    Open fffffa800428a1d0 - Miniport: fffffa80039711a0 Broadcom NetXtreme 57xx Gigabit Controller

 Protocol fffffa8003f6c820: WANARPV6
    Open fffffa8003f1c010 - Miniport: fffffa800399f1a0 WAN Miniport (IPv6)

 Protocol fffffa8003f6cd20: WANARP
    Open fffffa8003f1c670 - Miniport: fffffa80039d61a0 WAN Miniport (IP)

 Protocol fffffa8003eedb10: TCPIP6TUNNEL
    Open fffffa8003f33010 - Miniport: fffffa800396c1a0 isatap.company.com
    Open fffffa8003f0f010 - Miniport: fffffa80038f21a0 Teredo Tunneling Pseudo-Interface

 Protocol fffffa8003eeb580: TCPIPTUNNEL

 Protocol fffffa8003eeb010: TCPIP6
    Open fffffa8003f452e0 - Miniport: fffffa80039711a0 Broadcom NetXtreme 57xx Gigabit Controller

 Protocol fffffa8003ee90d0: TCPIP
    Open fffffa8003ffc480 - Miniport: fffffa80039711a0 Broadcom NetXtreme 57xx Gigabit Controller

 Protocol fffffa8003c56010: NDPROXY
    Open fffffa8003d41450 - Miniport: fffffa800399d1a0 WAN Miniport (L2TP)
    Open fffffa8003d41a30 - Miniport: fffffa800399d1a0 WAN Miniport (L2TP)

 Protocol fffffa80039ad790: RASPPPOE

 Protocol fffffa80039af4e0: NDISWAN
    Open fffffa8004737a10 - Miniport: fffffa8004a321a0 RAS Async Adapter
    Open fffffa8003bf8ac0 - Miniport: fffffa80039c21a0 WAN Miniport (PPTP)
    Open fffffa8003c5cac0 - Miniport: fffffa80039c01a0 WAN Miniport (PPPOE)
    Open fffffa8003c565a0 - Miniport: fffffa800399d1a0 WAN Miniport (L2TP)

I noticed this extension when I got a bugcheck from the 3rd-party custom protocol driver:

SYSTEM_PTE_MISUSE (da)
The stack trace identifies the guilty driver.
Arguments:
Arg1: 00000400, Type of error.
Arg2: f7a9a413
Arg3: 00000001
Arg4: 00000000

0: kd> kL
ChildEBP RetAddr 
f5c68a68 8083b6e1 nt!KeBugCheckEx+0x1b
f5c68a90 8083d478 nt!MiRemoveIoSpaceMap+0x5d
f5c68b38 f5b6ebea nt!MmUnmapIoSpace+0x10c
WARNING: Stack unwind information not available. Following frames may be wrong.
f5c68b90 f5b69abe protocol!foo2+0x28ac
f5c68bf4 f70fd4be protocol!foo+0x1aa0
f5c68c90 f70fd2fc NDIS!ndisInitializeBinding+0x189
f5c68d18 f70fce48 NDIS!ndisCheckAdapterBindings+0xd9
f5c68d98 f70fca66 NDIS!ndisCheckProtocolBindings+0xd2
f5c68dac 80949b7c NDIS!ndisWorkerThread+0x74
f5c68ddc 8088e062 nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

Arg1 0×400 one tells us this (from WinDbg help):

0×400 The base address of the I/O space mapping The number of pages to be freed 0 (Windows XP and later only) The caller is trying to free an I/O space mapping that the system is unaware of.

PTE  looks unknown indeed:

0: kd> !pte f7a9a413
VA f7a9a413
PDE at 00000000C0603DE8 PTE at 00000000C07BD4D0
contains 0000000000A87863 contains 0000000000000000
pfn a87 —DA–KWEV

We can see this protocol in the list:

0: kd> !ndiskd.protocols
 Protocol 89df10a0: CustomProtocol
    Open 89b4e6d8 - Miniport: 8a59d290 Broadcom BCM5708S NetXtreme II GigE (NDIS VBD Client)

 Protocol 8918f248: NDISUIO

 Protocol 89dd8008: TCPIP_WANARP
    Open 8a4da6f0 - Miniport: 8a50a9e8 WAN Miniport (IP)

 Protocol 89b4ec88: TCPIP

 Protocol 8a4cd5a0: NDPROXY
    Open 8a59b128 - Miniport: 8a58eab0 Direct Parallel
    Open 8a59b328 - Miniport: 8a58eab0 Direct Parallel
    Open 8a4f1580 - Miniport: 8a58a328 WAN Miniport (L2TP)
    Open 8a507008 - Miniport: 8a58a328 WAN Miniport (L2TP)

 Protocol 8a4e7008: RASPPPOE

 Protocol 8a5cb490: NDISWAN
    Open 8a59b988 - Miniport: 8a58eab0 Direct Parallel
    Open 8a5976c0 - Miniport: 8a591628 WAN Miniport (PPTP)
    Open 8a594468 - Miniport: 8a4e93f0 WAN Miniport (PPPOE)
    Open 8a4d3580 - Miniport: 8a58a328 WAN Miniport (L2TP)

- Dmitry Vostokov @ DumpAnalysis.org -

WDF and PNP BSOD: Case Study

Monday, March 24th, 2008

This morning I got the following bugcheck on my home Apple MacMini running Windows Vista:

IRQL_NOT_LESS_OR_EQUAL (a)
An attempt was made to access a pageable (or completely invalid) address at an interrupt request level (IRQL) that is too high.  This is usually caused by drivers using improper addresses.
If a kernel debugger is available get the stack backtrace.
Arguments:
Arg1: a112883e, memory referenced
Arg2: 0000001b, IRQL
Arg3: 00000000, bitfield :
 bit 0 : value 0 = read operation, 1 = write operation
 bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)
Arg4: 81c28750, address which referenced memory

READ_ADDRESS:  a112883e Paged pool

The address belongs to paged pool indeed:

0: kd> !pool a112883e
Pool page a112883e region is Paged pool
 a1128000 size:  6d0 previous size:    0  (Allocated)  Toke (Protected)
 a11286d0 size:    8 previous size:  6d0  (Free)       SeSd
 a11286d8 size:   a8 previous size:    8  (Allocated)  SpSy
 a1128780 size:   10 previous size:   a8  (Free)       AlEB
*a1128790 size:  1a0 previous size:   10  (Allocated) *KFlt
  Owning component : Unknown (update pooltag.txt)
 a1128930 size:  6d0 previous size:  1a0  (Allocated)  Toke (Protected)

Search for KFlt tag points to KeyMagic.sys:

C:\Windows\system32>findstr /S /m /l hKFlt *.sys
drivers\KeyMagic.sys
DriverStore\FileRepository\keymagic.inf_c8736569\KeyMagic.sys

When we look at the trap address we notice that it seems to be valid:

TRAP_FRAME:  85bdf8e8 -- (.trap 0xffffffff85bdf8e8)
ErrCode = 00000000
eax=a1128828 ebx=00000001 ecx=81d323c0 edx=00000000 esi=84ca6f38 edi=84ca6f40
eip=81c28750 esp=85bdf95c ebp=85bdf970 iopl=0 nv up ei pl zr na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000  efl=00010246
nt!KeSetEvent+0x4d:
81c28750 385816          cmp     byte ptr [eax+16h],bl      ds:0023:a112883e=01

However as explained in Another look at page faults post we have a page in transition and this violates IRQL contract:

0: kd> !pte a112883e
               VA a112883e
PDE at 00000000C0602840    PTE at 00000000C0508940
contains 000000001CEC5863  contains 000000001AFB48C2
pfn 1cec5 ---DA--KWEV                           not valid
                       Transition: 1afb4
                       Protect: 6 - ReadWriteExecute

When we look at stack trace parameters we notice that the first parameter passed to KeSetEvent function belongs to nonpaged pool:

STACK_TEXT: 
85bdf8e8 81c28750 badb0d00 00000000 00000000 nt!KiTrap0E+0x2ac
85bdf970 876394df 84ca6f0000000000 00000000 nt!KeSetEvent+0×4d
WARNING: Stack unwind information not available. Following frames may be wrong.
85bdf98c 8763a145 84ca68a0 8399e3b8 85bdf9ac KeyMagic+0×14df
85bdf99c 806f57a0 7b359920 7c98c800 85bdf9d4 KeyMagic+0×2145
85bdf9ac 806f514e 8399e3b8 8070e2a0 8399e3b8 Wdf01000!FxPkgPnp::PnpEventFailedOwnHardware+0×3b

0: kd> !pool 84ca6f00
Pool page 84ca6f00 region is Nonpaged pool
 84ca6000 size:  2b8 previous size:    0  (Allocated)  Thre (Protected)
 84ca62b8 size:   10 previous size:  2b8  (Free)       ....
 84ca62c8 size:   48 previous size:   10  (Allocated)  Vadl
 84ca6310 size:   30 previous size:   48  (Allocated)  Ntfn
 84ca6340 size:   38 previous size:   30  (Allocated)  usbp
 84ca6378 size:   98 previous size:   38  (Allocated)  NDam
 84ca6410 size:  188 previous size:   98  (Allocated)  NDoa
 84ca6598 size:    8 previous size:  188  (Free)       FOCX
 84ca65a0 size:   30 previous size:    8  (Allocated)  UHUB
 84ca65d0 size:   20 previous size:   30  (Allocated)  Wnln
 84ca65f0 size:   28 previous size:   20  (Allocated)  Io 
 84ca6618 size:   18 previous size:   28  (Allocated)  Ala6
 84ca6630 size:   98 previous size:   18  (Allocated)  NDam
*84ca66c8 size:  938 previous size:   98  (Allocated) *KeyM
  Owning component : Unknown (update pooltag.txt)

However it is not a pointer to a valid _KEVENT structure:

0: kd> dt -r _KEVENT 84ca6f00
Wdf01000!_KEVENT
   +0x000 Header           : _DISPATCHER_HEADER
      +0x000 Type             : 0xc8 ''
      +0x001 Abandoned        : 0x87 ''
      +0x001 Absolute         : 0x87 ''
      +0x001 NpxIrql          : 0x87 ''
      +0x001 Signalling       : 0x87 ''
      +0x002 Size             : 0x12 ''
      +0x002 Hand             : 0x12 ''
      +0x003 Inserted         : 0xa1 ''
      +0x003 DebugActive      : 0xa1 ''
      +0x003 DpcActive        : 0xa1 ''
      +0x000 Lock             : -1592621112
      +0x004 SignalState      : -1592621112
      +0x008 WaitListHead     : _LIST_ENTRY [ 0x40000 - 0x0 ]
         +0x000 Flink            : 0x00040000 _LIST_ENTRY
         +0x004 Blink            : (null)

Moreover we see from disassembly and nonpaged pool entry contents that KeSetEvent function tried to dereference wrong WaitListHead that points to paged pool (the same pool entry that caused the bugcheck):

0: kd> uf nt!KeSetEvent
nt!KeSetEvent:
81c28703 mov     edi,edi
81c28705 push    ebp
81c28706 mov     ebp,esp
81c28708 push    ecx
81c28709 push    ecx
81c2870a push    ebx
81c2870b push    esi
81c2870c mov     esi,dword ptr [ebp+8]
81c2870f xor     ebx,ebx
81c28711 inc     ebx
81c28712 cmp     byte ptr [esi],0
81c28715 push    edi
81c28716 jne     nt!KeSetEvent+0x27 (81c2872a)

nt!KeSetEvent+0x15:
81c28718 cmp     dword ptr [esi+4],ebx
81c2871b jne     nt!KeSetEvent+0x27 (81c2872a)

nt!KeSetEvent+0x1a:
81c2871d cmp     byte ptr [ebp+10h],0
81c28721 jne     nt!KeSetEvent+0x27 (81c2872a)

nt!KeSetEvent+0x20:
81c28723 mov     eax,ebx
81c28725 jmp     nt!KeSetEvent+0xcf (81c287d6)

nt!KeSetEvent+0x27:
81c2872a xor     ecx,ecx
81c2872c call    dword ptr [nt!_imp_KeAcquireQueuedSpinLockRaiseToSynch (81c010a4)]
81c28732 mov     byte ptr [ebp+8],al ; clears the first byte of 84ca6f00 so PKEVENT could have been any 84ca6fXX
81c28735 mov     eax,dword ptr [esi+4]
81c28738 test    eax,eax
81c2873a mov     dword ptr [ebp-4],eax
81c2873d mov     dword ptr [esi+4],ebx
81c28740 jne     nt!KeSetEvent+0×9a (81c287a1)

nt!KeSetEvent+0x3f:
81c28742 lea     edi,[esi+8]
81c28745 cmp     dword ptr [edi],edi
81c28747 je      nt!KeSetEvent+0x9a (81c287a1)

nt!KeSetEvent+0x46:
81c28749 cmp     byte ptr [esi],0
81c2874c mov     eax,dword ptr [edi]
81c2874e jne     nt!KeSetEvent+0x70 (81c28775)

nt!KeSetEvent+0x4d:
81c28750 cmp     byte ptr [eax+16h],bl
81c28753 mov     ecx,dword ptr [eax+8]
81c28756 push    dword ptr [ebp+0Ch]
81c28759 jne     nt!KeSetEvent+0x5e (81c28761)

nt!KeSetEvent+0x58:
81c2875b movzx   edx,word ptr [eax+14h]
81c2875f jmp     nt!KeSetEvent+0x63 (81c28766)

nt!KeSetEvent+0x5e:
81c28761 mov     edx,100h

nt!KeSetEvent+0x63:
81c28766 call    nt!KiUnwaitThread (81ca9097)
81c2876b mov     eax,dword ptr [edi]
81c2876d cmp     eax,edi
81c2876f je      nt!KeSetEvent+0x9a (81c287a1)

nt!KeSetEvent+0x6e:
81c28771 jmp     nt!KeSetEvent+0x4d (81c28750)

nt!KeSetEvent+0x70:
81c28775 cmp     byte ptr [eax+16h],bl
81c28778 mov     ecx,dword ptr [eax+8]
81c2877b push    dword ptr [ebp+0Ch]
81c2877e je      nt!KeSetEvent+0x8d (81c28794)

nt!KeSetEvent+0x7b:
81c28780 mov     edx,100h
81c28785 call    nt!KiUnwaitThread (81ca9097)
81c2878a mov     eax,dword ptr [edi]
81c2878c cmp     eax,edi
81c2878e je      nt!KeSetEvent+0x9a (81c287a1)

nt!KeSetEvent+0x8b:
81c28790 jmp     nt!KeSetEvent+0x70 (81c28775)

nt!KeSetEvent+0x8d:
81c28794 and     dword ptr [esi+4],0
81c28798 movzx   edx,word ptr [eax+14h]
81c2879c call    nt!KiUnwaitThread (81ca9097)

nt!KeSetEvent+0x9a:
81c287a1 cmp     byte ptr [ebp+10h],0
81c287a5 je      nt!KeSetEvent+0xb2 (81c287b9)

nt!KeSetEvent+0xa0:
81c287a7 mov     eax,dword ptr fs:[00000124h]
81c287ad mov     cl,byte ptr [ebp+8]
81c287b0 or      dword ptr [eax+68h],8
81c287b4 mov     byte ptr [eax+5Eh],cl
81c287b7 jmp     nt!KeSetEvent+0xcc (81c287d3)

nt!KeSetEvent+0xb2:
81c287b9 mov     ecx,dword ptr fs:[20h]
81c287c0 add     ecx,418h
81c287c6 call    nt!KeReleaseQueuedSpinLockFromDpcLevel (81c8bf0c)
81c287cb push    dword ptr [ebp+8]
81c287ce call    nt!KiExitDispatcher (81ca9c12)

nt!KeSetEvent+0xcc:
81c287d3 mov     eax,dword ptr [ebp-4]

nt!KeSetEvent+0xcf:
81c287d6 pop     edi
81c287d7 pop     esi
81c287d8 pop     ebx
81c287d9 leave
81c287da ret     0Ch

0: kd> dd 84ca6f00 84ca6fff
84ca6f00 a11287c8 a11287c8 00040000 00000000
84ca6f10 a11287e0 a11287e0 00040000 00000000
84ca6f20 a11287f8 a11287f8 00040000 00000000
84ca6f30 a1128810 a1128810 00040000 00000001
84ca6f40 a1128828 a1128828 00040000 00000000
84ca6f50 a1128840 a1128840 00040000 00000000
84ca6f60 a1128858 a1128858 00040000 00000000
84ca6f70 a1128888 a1128888 00040000 00000000
84ca6f80 a11288a0 a11288a0 00040000 00000000
84ca6f90 a1128870 a1128870 00040000 00000000
84ca6fa0 a11288b8 a11288b8 00040000 00000000
84ca6fb0 a11288d0 a11288d0 00040000 00000000
84ca6fc0 a11288e8 a11288e8 00040000 00000000
84ca6fd0 a1128900 a1128900 00040000 00000000
84ca6fe0 a1128918 a1128918 5e55aec0 6003be28
84ca6ff0 60181fe8 00000000 00000000 00000000

0: kd> !pool a11287c8
Pool page a11287c8 region is Paged pool
 a1128000 size:  6d0 previous size:    0  (Allocated)  Toke (Protected)
 a11286d0 size:    8 previous size:  6d0  (Free)       SeSd
 a11286d8 size:   a8 previous size:    8  (Allocated)  SpSy
 a1128780 size:   10 previous size:   a8  (Free)       AlEB
*a1128790 size:  1a0 previous size:   10  (Allocated) *KFlt
  Owning component : Unknown (update pooltag.txt)
 a1128930 size:  6d0 previous size:  1a0  (Allocated)  Toke (Protected)

Let’s look at our stack trace:

0: kd> !thread 82f49020 1f
THREAD 82f49020  Cid 0004.0034  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
IRP List:
    8391e008: (0006,02b0) Flags: 00000000  Mdl: 00000000
Not impersonating
DeviceMap                 85c03048
Owning Process            82f00ab0       Image:         System
Wait Start TickCount      4000214        Ticks: 0
Context Switch Count      21886            
UserTime                  00:00:00.000
KernelTime                00:00:00.421
Win32 Start Address nt!ExpWorkerThread (0x81c78ea3)
Stack Init 85be0000 Current 85bdf7c0 Base 85be0000 Limit 85bdd000 Call 0
Priority 14 BasePriority 12 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr 
85bdf8e8 81c28750 nt!KiTrap0E+0x2ac (TrapFrame @ 85bdf8e8)
85bdf970 876394df nt!KeSetEvent+0x4d
WARNING: Stack unwind information not available. Following frames may be wrong.
85bdf98c 8763a145 KeyMagic+0x14df
85bdf99c 806f57a0 KeyMagic+0x2145
85bdf9ac 806f514e Wdf01000!FxPkgPnp::PnpEventFailedOwnHardware+0x3b
85bdf9d4 806f5ea9 Wdf01000!FxPkgPnp::PnpEnterNewState+0x15c
85bdf9fc 806f61b3 Wdf01000!FxPkgPnp::PnpProcessEventInner+0x1f5
85bdfa20 806ecf6b Wdf01000!FxPkgPnp::PnpProcessEvent+0x1c8
85bdfa2c 806f34b4 Wdf01000!FxPkgPnp::PnpSurpriseRemoval+0x29
85bdfa38 806edf86 Wdf01000!FxPkgFdo::_PnpSurpriseRemoval+0x10
85bdfa5c 806d7d0a Wdf01000!FxPkgPnp::Dispatch+0x26e
85bdfa68 806d7f0f Wdf01000!FxDevice::Dispatch+0x7f
85bdfa84 81c27f83 Wdf01000!FxDevice::DispatchWithLock+0x5d
85bdfa9c a4966e7f nt!IofCallDriver+0x63
85bdfac0 a496c9ae hidbth!HidBthCallDriverSynchronous+0x55
85bdfae0 85ac5a5d hidbth!HidBthPnP+0x68
85bdfaf4 85acd4c2 HIDCLASS!HidpCallDriver+0x3f
85bdfb10 85acd62e HIDCLASS!HidpFdoPnp+0x60
85bdfb20 85ac64fd HIDCLASS!HidpIrpMajorPnp+0x1e
85bdfb30 81c27f83 HIDCLASS!HidpMajorHandler+0x79
85bdfb48 81daf465 nt!IofCallDriver+0x63
85bdfb7c 81daf6cb nt!IopSynchronousCall+0xce
85bdfbd8 81da5da4 nt!IopRemoveDevice+0xd5
85bdfc00 81da5c97 nt!PnpSurpriseRemoveLockedDeviceNode+0xbd
85bdfc14 81da5f17 nt!PnpDeleteLockedDeviceNode+0x1f
85bdfc44 81daa554 nt!PnpDeleteLockedDeviceNodes+0x4c
85bdfd04 81daabe1 nt!PnpProcessQueryRemoveAndEject+0x572
85bdfd1c 81da9743 nt!PnpProcessTargetDeviceEvent+0x38
85bdfd44 81c78fa0 nt!PnpDeviceEventWorker+0x201
85bdfd7c 81e254e0 nt!ExpWorkerThread+0xfd
85bdfdc0 81c9159e nt!PspSystemThreadStartup+0x9d
00000000 00000000 nt!KiThreadStartup+0x16

IRP and device examination shows that KeyMagic is a lower filter driver to bluetooth HID driver and an upper filter driver to BthEnum (see Bluetooth Driver Stack WDK article):

0: kd> !irp 8391e008
Irp is active with 16 stacks 14 is current (= 0x8391e24c)
 No Mdl: No System Buffer: Thread 82f49020:  Irp stack trace. 
     cmd  flg cl Device   File     Completion-Context
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0  0 00000000 00000000 00000000-00000000

   Args: 00000000 00000000 00000000 00000000
>[ 1b,17]   0 e1 a1b9b120 00000000 a4966d36-85bdfab0 Success Error Cancel pending
        \Driver\KeyMagic hidbth!HidBthSynchronousCompletion

   Args: 00000000 00000000 00000000 00000000
 [ 1b,17]   0  0 8a1fc030 00000000 00000000-00000000   
        \Driver\HidBth
   Args: 00000000 00000000 00000000 00000000
 [ 1b,17]   0  0 8a1fc030 00000000 00000000-00000000   
        \Driver\HidBth
   Args: 00000000 00000000 00000000 00000000

0: kd> !devobj 8a1fc030
Device object (8a1fc030) is for:
 _HID00000006 \Driver\HidBth DriverObject 836225e0
Current Irp 00000000 RefCount 0 Type 00000022 Flags 00002050
Dacl 85c60218 DevExt 8a1fc0e8 DevObjExt 8a1fce98
ExtensionFlags (0x00000800) 
                             Unknown flags 0x00000800
AttachedTo (Lower) a1b9b120 \Driver\KeyMagic
Device queue is not busy.

0: kd> !devobj a1b9b120
Device object (a1b9b120) is for:
  \Driver\KeyMagic DriverObject 83712d70
Current Irp 00000000 RefCount 0 Type 00000022 Flags 00002004
DevExt 84ca68a0 DevObjExt a1b9b1f0
ExtensionFlags (0x00000800) 
                             Unknown flags 0x00000800
AttachedDevice (Upper) 8a1fc030 \Driver\HidBth
AttachedTo (Lower) 8a1ef030 \Driver\BthEnum
Device queue is not busy.

0: kd> !devstack 8a1ef030
  !DevObj   !DrvObj            !DevExt   ObjectName
  8a1fc030  \Driver\HidBth     8a1fc0e8  _HID00000006
  a1b9b120  \Driver\KeyMagic   84ca68a0 
> 8a1ef030  \Driver\BthEnum    8a1ef0e8  00000068

lmv command doesn’t show detailed module information:

0: kd> lmv m KeyMagic
start    end        module name
87638000 87642000   KeyMagic   (no symbols)          
    Loaded symbol image file: KeyMagic.sys
    Image path: \SystemRoot\system32\DRIVERS\KeyMagic.sys
    Image name: KeyMagic.sys
    Timestamp:        Thu Aug 30 22:59:01 2007 (46D73DA5)
    CheckSum:         0000B906
    ImageSize:        0000A000
    Translations:     0000.04b0 0000.04e0 0409.04b0 0409.04e0

But dumping the module contents shows more (Unknown Component  pattern):

0: kd> dc 87638000 87642000
...
...
...
8763b120  \.r.e.g.i.s.t.r.
8763b130  y.\.m.a.c.h.i.n.
8763b140  e.\.S.y.s.t.e.m.
8763b150  \.C.u.r.r.e.n.t.
8763b160  C.o.n.t.r.o.l.S.
8763b170  e.t.\.S.e.r.v.i.
8763b180  c.e.s.\.k.e.y.m.
8763b190  a.g.i.c.....FILT
8763b1a0  ER_EXTENSION....
8763b1b0  NEW_LAYOUT..OLD_
8763b1c0  LAYOUT..UNKNOWN_
8763b1d0  LAYOUT..EXTERNAL
8763b1e0  _BLUETOOTH..EXTE
8763b1f0  RNAL_CORDED.INTE
8763b200  RNAL....UNKNOWN_
8763b210  TYPE....JIS.ANSI
8763b220  ....ISO.UNKNOWN_
8763b230  LANG............
8763b240  u.....%.........
8763b250  ................
8763b260  ............K.m.
8763b270  d.f.L.i.b.r.a.r.
8763b280  y...RSDS.....W.M
8763b290  .V..A..e....c:\b
8763b2a0  wa\applekeyboard
8763b2b0  win-200.1.4\srcr
8763b2c0  oot\applekeyboar
8763b2d0  d\objfre_wlh_x86
8763b2e0  \i386\KeyMagic.p
8763b2f0  db…………..
8763b300  …………….


Therefore we have enough evidence for KeyMagic.sys to contact the vendor for updates or remove it. The latter is better because I don’t use Apple wireless keyboard but the driver is present on my system. To be absolutely sure we can enable IRQL checking in Driver Verifier for KeyMagic.sys.

- Dmitry Vostokov @ DumpAnalysis.org -

New Portal Design

Saturday, March 22nd, 2008

Main site www.dumpanalysis.org has undergone the small “redesign” to become more like the blog BSOD theme. Enjoy :-)

- Dmitry Vostokov @ DumpAnalysis.org -

Windows® Device Drivers

Thursday, March 20th, 2008

Why do we need yet another book about device drivers? There are couple of reasons here:

  1. Old books are more about developing the narrow range of legacy drivers than troubleshooting and debugging them.

  2. New books shift towards WDF and ignore legacy drivers.

  3. Windows Internals book is too big and something lightweight is desperately needed.

  4. No published driver books use UML as communication device and discuss driver developement as software factory.

  5. Existing books mostly view device drivers as hardware device drivers.

I started collecting and organizing information about Windows drivers 2 years ago and published a few selected materials so you can get an approximate flavour of what is expected in the forthcoming book scheduled for the next year:

UML and Device Drivers

  • Title:  Windows Device Drivers: An Introduction
  • Author: Dmitry Vostokov
  • Paperback: 128 pages
  • ISBN-13: 978-0-9558328-4-0
  • Publisher: Opentask (15 Apr 2009)
  • Language: English
  • Product Dimensions: 22.86 x 15.24

- Dmitry Vostokov @ DumpAnalysis.org -

WinDbg book to be published after MDAA V1

Thursday, March 20th, 2008

This is a forthcoming reference book for technical support and escalation engineers troubleshooting and debugging complex software issues. The book is also invaluable for software maintenance and development engineers debugging unmanaged, managed and native code.

  • Title: Windows® Debugging Notebook: Essential Concepts, WinDbg Commands and Tools
  • Author: Dmitry Vostokov
  • Hardcover: 256 pages
  • ISBN-13: 978-0-9558328-5-7
  • Publisher: Opentask (1 September 2008)
  • Language: English
  • Product Dimensions: 22.86 x 15.24

- Dmitry Vostokov @ DumpAnalysis.org -

Memory Search Revisited

Thursday, March 20th, 2008

We all know about s memory search WinDbg command but it only searches the current virtual memory range. This is fine if we have a kernel memory or a user dump where we have uniform virtual space but for complete memory dumps we have many virtual to physical address mappings to cover user space of various processes. This is better illustrated on the following highly simplified picture where the typical current virtual space in a complete memory dump is enclosed in the shadowed box and consists of the kernel space and process A virtual address space ranges:

 

Therefore some data will be present in physical memory but not accessible through virtual memory search. To search through all physical memory there is !search WinDbg command and by default it searches for specific 32-bit value on 32-bit Windows and 64-bit value on 64-bit Windows. The latter means that we can search for 8 character string fragments on 64-bit Windows. For example, if we want to search for occurrences of ”ImaSrv.exe” string we can specify “ImaS” on 32-bit platform and “ImaSrv.e” on 64-bit platform. Taking into account little endian byte ordering we get the following hexadecimal equivalents:

0: kd> .formats 'SamI'
Evaluate expression:
  Hex:     53616d49
  Decimal: 1398893897
  Octal:   12330266511
  Binary:  01010011 01100001 01101101 01001001
  Chars:   SamI
  Time:    Wed Apr 30 22:38:17 2014
  Float:   low 9.68201e+011 high 0
  Double:  6.91145e-315

0: kd> .formats 'e.vrSamI'
Evaluate expression:
  Hex:     652e7672`53616d49
  Decimal: 7290895080156654921
  Octal:   0624563547112330266511
  Binary:  01100101 00101110 01110110 01110010 01010011 01100001 01101101 01001001
  Chars:   e.vrSamI
  Time:    Mon Dec  5 23:20:15.665 24704 (GMT+0)
  Float:   low 9.68201e+011 high 5.14923e+022
  Double:  2.46885e+179

Physical memory search gives us plenty of results:

0: kd> !search 53616d49
Searching PFNs in range 00000001 - 0013FFFF for [53616D49 - 53616D49]

Pfn      Offset   Hit      Va       Pte     
- - - - - - - - - - - - - - - - - - - - - - - - - - -
000079FA 000004C4 53616D49 A3AFB4C4 C051D7D8
 a3afb340+0x184   : Proc (Protected)  -- Process objects
00011442 00000848 53616D49 66EC2848 C0337610
00011442 0000093C 53616D49 66EC293C C0337610
0001328A 000009F4 43616D49 672E59F4 C0339728
000156F6 000009F4 43616D49 672E59F4 C0339728
00018C7C 000009DC 43616D49 671F49DC C0338FA0
0001ADF0 000003D4 52616D49 00000000 DC3E3B48
0001ADF0 000003E4 52616D49 00000000 DC3E3B48
00020BCE 000009DC 43616D49 671F49DC C0338FA0
...
...
...

We can dump either a virtual address if it is available and valid by using normal d* commands or dump a physical address by using their !d* extension equivalents, for example:

Pfn      Offset   Hit      Va       Pte     
- - - - - - - - - - - - - - - - - - - - - - - - - - -
00011442 00000848 53616D49 66EC2848 C0337610

 0: kd> !dc 11442000+00000848
#11442848 53616d49 65747379 6c642e6d 0000006c ImaSystem.dll...
#11442858 00000000 00000000 00000000 45cd0da0 ...............E
#11442868 00000000 0000293c 00000001 00000012 ....<)..........
#11442878 00000012 00002888 000028d0 00002918 .....(...(...)..
#11442888 00001160 000010b0 00001020 00001000 `....... .......
#11442898 00001130 00001010 000010a0 00001030 0...........0...
#114428a8 000020d8 000020cc 00001300 000013c0 . ... ..........
#114428b8 00001200 00001050 00001040 00001080 ....P...@.......

Note: Physical addresses are formed from PFN (Page Frame Numbers) by shifting them to the left by 12 bits (by adding 3 zeroes to the left). For example: 00011442 -> 11442000.

The cool feature of !search command is that it automatically recognizes pool tags and in our case it has found the process object: 

Pfn      Offset   Hit      Va       Pte     
- - - - - - - - - - - - - - - - - - - - - - - - - - -
000079FA 000004C4 53616D49 A3AFB4C4 C051D7D8
 a3afb340+0×184   : Proc (Protected)  — Process objects



0: kd> !pool A3AFB4C4
Pool page a3afb340 region is Nonpaged pool
 a3afb000 size:  120 previous size:    0  (Allocated)  MQAC
 a3afb120 size:   20 previous size:  120  (Allocated)  VadS
 a3afb140 size:   98 previous size:   20  (Allocated)  File (Protected)
 a3afb1d8 size:   30 previous size:   98  (Allocated)  MQAC
 a3afb208 size:   20 previous size:   30  (Allocated)  VadS
 a3afb228 size:   28 previous size:   20  (Free)       CcBc
 a3afb250 size:   30 previous size:   28  (Allocated)  Vad
 a3afb280 size:   30 previous size:   30  (Allocated)  Vad
 a3afb2b0 size:   20 previous size:   30  (Allocated)  VadS
 a3afb2d0 size:   40 previous size:   20  (Allocated)  SeTd
 a3afb310 size:   30 previous size:   40  (Allocated)  Vad
*a3afb340 size:  298 previous size:   30  (Allocated) *Proc (Protected)
  Pooltag Proc : Process objects, Binary : nt!ps

 a3afb5d8 size:    8 previous size:  298  (Free)       Irp
 a3afb5e0 size:   20 previous size:    8  (Allocated)  VadS
 a3afb600 size:    8 previous size:   20  (Free)       Irp
 a3afb608 size:   30 previous size:    8  (Allocated)  Even (Protected)
 a3afb638 size:   30 previous size:   30  (Allocated)  Vad
 a3afb668 size:   40 previous size:   30  (Allocated)  Vadl
 a3afb6a8 size:   70 previous size:   40  (Allocated)  NWFS
 a3afb718 size:   30 previous size:   70  (Allocated)  Vad
 a3afb748 size:   28 previous size:   30  (Allocated)  NpFr Process: a3afb360
 a3afb770 size:   98 previous size:   28  (Allocated)  File (Protected)
 a3afb808 size:   60 previous size:   98  (Allocated)  MmCa
 a3afb868 size:   98 previous size:   60  (Allocated)  File (Protected)
 a3afb900 size:   30 previous size:   98  (Allocated)  Even (Protected)
 a3afb930 size:   20 previous size:   30  (Allocated)  VadS
 a3afb950 size:   98 previous size:   20  (Allocated)  File (Protected)
 a3afb9e8 size:   30 previous size:   98  (Allocated)  MQAC
 a3afba18 size:  120 previous size:   30  (Allocated)  MQAC
 a3afbb38 size:   50 previous size:  120  (Allocated)  NpFc Process: a5659d88
 a3afbb88 size:   20 previous size:   50  (Allocated)  Port
 a3afbba8 size:   98 previous size:   20  (Allocated)  File (Protected)
 a3afbc40 size:   30 previous size:   98  (Allocated)  MQAC
 a3afbc70 size:  120 previous size:   30  (Allocated)  MQAC
 a3afbd90 size:  270 previous size:  120  (Allocated)  Thre (Protected)

0: kd> dc A3AFB4C4 l10
a3afb4c4  53616d49 652e7672 00006578 00000000  ImaSrv.exe......
a3afb4d4  00000000 00000000 00000000 a3afbfd4  ................
a3afb4e4  a282fe44 00000000 f7a60500 0000004c  D...........L...
a3afb4f4  001f07fb 00008005 00000000 7ffdd000  ................

Seems the search has found ImageFileName field of _EPROCESS structure. The field has 0×164 offset and we can dump the whole structure:

0: kd> dt _EPROCESS A3AFB4C4-0x164
ntdll!_EPROCESS
   +0x000 Pcb              : _KPROCESS
   +0x078 ProcessLock      : _EX_PUSH_LOCK
   +0x080 CreateTime       : _LARGE_INTEGER 0x1c86f66`5b95204a
   +0x088 ExitTime         : _LARGE_INTEGER 0x0
   +0x090 RundownProtect   : _EX_RUNDOWN_REF
   +0x094 UniqueProcessId  : 0x000009d0
   +0x098 ActiveProcessLinks : _LIST_ENTRY [ 0xa3af2598 - 0xa3b0a0b8 ]
   +0x0a0 QuotaUsage       : [3] 0x17030
   +0x0ac QuotaPeak        : [3] 0x18028
   +0x0b8 CommitCharge     : 0x37b6
   +0x0bc PeakVirtualSize  : 0x132d4000
   +0x0c0 VirtualSize      : 0x12d64000
   +0x0c4 SessionProcessLinks : _LIST_ENTRY [ 0xa3af25c4 - 0xa3b0a0e4 ]
   +0x0cc DebugPort        : (null)
   +0x0d0 ExceptionPort    : 0xd738e828
   +0x0d4 ObjectTable      : 0xdc23a008 _HANDLE_TABLE
   +0x0d8 Token            : _EX_FAST_REF
   +0x0dc WorkingSetPage   : 0x11741f
   +0x0e0 AddressCreationLock : _KGUARDED_MUTEX
   +0x100 HyperSpaceLock   : 0
   +0x104 ForkInProgress   : (null)
   +0x108 HardwareTrigger  : 0
   +0x10c PhysicalVadRoot  : 0xa3c21448 _MM_AVL_TABLE
   +0x110 CloneRoot        : (null)
   +0x114 NumberOfPrivatePages : 0x318d
   +0x118 NumberOfLockedPages : 7
   +0x11c Win32Process     : 0xbc33d968
   +0x120 Job              : (null)
   +0x124 SectionObject    : 0xdc2710c8
   +0x128 SectionBaseAddress : 0x00400000
   +0x12c QuotaBlock       : 0xa3bb2f38 _EPROCESS_QUOTA_BLOCK
   +0x130 WorkingSetWatch  : (null)
   +0x134 Win32WindowStation : 0x00000078
   +0x138 InheritedFromUniqueProcessId : 0x00000228
   +0x13c LdtInformation   : (null)
   +0x140 VadFreeHint      : (null)
   +0x144 VdmObjects       : (null)
   +0x148 DeviceMap        : 0xd7d0ff30
   +0x14c Spare0           : [3] (null)
   +0x158 PageDirectoryPte : _HARDWARE_PTE_X86
   +0x158 Filler           : 0
   +0x160 Session          : 0xf79d5000
   +0×164 ImageFileName    : [16]  “ImaSrv.exe”
   +0×174 JobLinks         : _LIST_ENTRY [ 0×0 - 0×0 ]
   +0×17c LockedPagesList  : (null)
   +0×180 ThreadListHead   : _LIST_ENTRY [ 0xa3afbfd4 - 0xa282fe44 ]
   +0×188 SecurityPort     : (null)
   +0×18c PaeTop           : 0xf7a60500
   +0×190 ActiveThreads    : 0×4c
   +0×194 GrantedAccess    : 0×1f07fb
   +0×198 DefaultHardErrorProcessing : 0×8005
   +0×19c LastThreadExitStatus : 0
   +0×1a0 Peb              : 0×7ffdd000 _PEB
   +0×1a4 PrefetchTrace    : _EX_FAST_REF
   +0×1a8 ReadOperationCount : _LARGE_INTEGER 0xf01d3
   +0×1b0 WriteOperationCount : _LARGE_INTEGER 0×3b08c
   +0×1b8 OtherOperationCount : _LARGE_INTEGER 0×67845
   +0×1c0 ReadTransferCount : _LARGE_INTEGER 0×9b087eec
   +0×1c8 WriteTransferCount : _LARGE_INTEGER 0×39f8a27a
   +0×1d0 OtherTransferCount : _LARGE_INTEGER 0×25dd749
   +0×1d8 CommitChargeLimit : 0
   +0×1dc CommitChargePeak : 0×394b
   +0×1e0 AweInfo          : (null)
   +0×1e4 SeAuditProcessCreationInfo : _SE_AUDIT_PROCESS_CREATION_INFO
   +0×1e8 Vm               : _MMSUPPORT
   +0×230 MmProcessLinks   : _LIST_ENTRY [ 0xa3af2730 - 0xa3b0a250 ]
   +0×238 ModifiedPageCount : 0xc835
   +0×23c JobStatus        : 0
   +0×240 Flags            : 0×4d0801
   +0×240 CreateReported   : 0y1
   +0×240 NoDebugInherit   : 0y0
   +0×240 ProcessExiting   : 0y0
   +0×240 ProcessDelete    : 0y0
   +0×240 Wow64SplitPages  : 0y0
   +0×240 VmDeleted        : 0y0
   +0×240 OutswapEnabled   : 0y0
   +0×240 Outswapped       : 0y0
   +0×240 ForkFailed       : 0y0
   +0×240 Wow64VaSpace4Gb  : 0y0
   +0×240 AddressSpaceInitialized : 0y10
   +0×240 SetTimerResolution : 0y0
   +0×240 BreakOnTermination : 0y0
   +0×240 SessionCreationUnderway : 0y0
   +0×240 WriteWatch       : 0y0
   +0×240 ProcessInSession : 0y1
   +0×240 OverrideAddressSpace : 0y0
   +0×240 HasAddressSpace  : 0y1
   +0×240 LaunchPrefetched : 0y1
   +0×240 InjectInpageErrors : 0y0
   +0×240 VmTopDown        : 0y0
   +0×240 ImageNotifyDone  : 0y1
   +0×240 PdeUpdateNeeded  : 0y0
   +0×240 VdmAllowed       : 0y0
   +0×240 SmapAllowed      : 0y0
   +0×240 CreateFailed     : 0y0
   +0×240 DefaultIoPriority : 0y000
   +0×240 Spare1           : 0y0
   +0×240 Spare2           : 0y0
   +0×244 ExitStatus       : 259
   +0×248 NextPageColor    : 0xf91e
   +0×24a SubSystemMinorVersion : 0 ”
   +0×24b SubSystemMajorVersion : 0×4 ”
   +0×24a SubSystemVersion : 0×400
   +0×24c PriorityClass    : 0×6 ”
   +0×250 VadRoot          : _MM_AVL_TABLE
   +0×270 Cookie           : 0×5a583219

We can also see that by default !search command finds entries differing in a single bit, for example:

Pfn      Offset   Hit      Va       Pte     
- - - - - - - - - - - - - - - - - - - - - - - - - - -
...
...
...
00011442 0000093C 53616D49 66EC293C C0337610
0001328A 000009F4 43616D49 672E59F4 C0339728


0: kd> !dc 0001328A9F4
#1328a9f4 43616d49 6f6d6d6f 64702e6e 00000062 ImaCommon.pdb...
#1328aa04 672e7170 00000000 00000000 ffffffff pq.g............
#1328aa14 00000000 00000000 672e5a04 00000000 .........Z.g....
#1328aa24 00000000 00000000 00000001 672e5a1c .............Z.g
#1328aa34 00000000 00000000 00000000 672e7170 ............pq.g
#1328aa44 672e5a24 00000000 00000000 00004c24 $Z.g........$L..
#1328aa54 00000000 00000000 00000000 00000000 ................
#1328aa64 00000000 672e7138 00000000 ffffffff ....8q.g........

In the case of kernel memory dumps physical memory search might be better alternative to virtual memory search if we need to see pool tags corresponding to search hits or search for data differing in some bits, for example:

3: kd> .ignore_missing_pages 1
Suppress kernel summary dump missing page error message

3: kd> s -d 80000000 L?20000000 53616d49
86a6eeec  53616d49 652e7672 00006578 00000000  ImaSrv.exe......

3: kd> !search 53616d49
Debuggee is a kernel summary dump, some physical pages may not be present.
Searches will miss hits from those pages.
Searching PFNs in range 00000001 - 0007FFFF for [53616D49 - 53616D49]

Pfn      Offset   Hit      Va       Pte     
- - - - - - - - - - - - - - - - - - - - - - - - - - -
00005DED 00000EEC 53616D49 86A6EEEC C021A9B8
 86a6ed68+0x184   : Proc (Protected)  -- Process objects
Search done.

- Dmitry Vostokov @ DumpAnalysis.org -