Ntdebugging Blog

Remoting Your Debug Crash Cart With KDNET

ntdebug — Fri, 10 May 2013 00:58:49 GMT

This is Christian Sträßner from the Global Escalation Services team based in Munich, Germany.

Back in January, my colleague Ron Stock posted an interesting article about Kernel Debugging using a serial cable: How to Setup a Debug Crash Cart to Prevent Your Server from Flat Lining

Today we look at a new kernel debugging transport introduced in Windows 8 and Windows Server 2012 that makes the cabling much easier, now a network cable can be used as a debug cable. The new KDNET transport utilizes a PCI Ethernet network card in the Target. Most major NIC Vendors have compatible NICs. You can find a list of supported NICs here:

http://msdn.microsoft.com/en-us/library/windows/hardware/hh830880.aspx

Note that this will not work with Wireless or USB attached NICs in the Target.

In the example below, we utilized an Acer AC 100 Server as the Target. It ships with an onboard Intel 82579LM Gigabit NIC:

The great thing about KDNET is that the NIC can still be used for normal network activity. The “Microsoft Kernel Debug Network Adapter” driver is the magic behind this. When KDNET.DLL is active, the NIC’s driver will be “banged out” and KDNET takes control of the NIC.

BCD Configuration

To configure KDNET, you first need to determine the IPv4 Address of the machine with the debugger. In our example, ipconfig.exe tells us that it is 192.168.1.35:

Next go to your Target machine.

The kernel debug settings used to configure KDNET are stored globally in the BCD Store in the {dbgsettings} area. The kernel debug settings apply to all boot entries.

Use bcdedit.exe /dbgsettings net hostip:<addr>port:<port> to set the transport to KDNET, the IP Address of the debugger and the port. You can connect multiple targets to the same debug host by using a different port for each target.

BCD will generate a cryptographic key for you automatically the first time. You can generate a new cryptographic key by appending the ‘newkey’ keyword. Copy the ‘Key’ to a secure location - you will need it in the debugger.

You can display the debug settings using: bcdedit /dbgsettings

Next, for safety, copy the {current} entry to a new entry (bcdedit /copy {current} /d <description>).

Then enable kernel debugging on the copy (bcdedit.exe /debug {new-guid} on).

If required, also use this (new) entry to enable the checked kernel (bcdedit /set {new-guid} hal <path> and bcdedit.exe /set {new-guid} kernel <path>).

Debugger

On your Debugger Machine open WinDbg->File->Kernel Debugging (Ctrl-K) and choose the NET tab:

Copy and paste the ‘Key’ here and set the port to the value specified on the Target (the default is 50000):

Next a dialog from Windows Firewall might pop up (depending on your configuration). You want to allow access at this point.

You need to make sure that your debug host machine allows inbound UDP traffic on the configured port (50000 in this example, and by default) for the network type in use.

If your company has implemented IPSec Policies, make sure you have exceptions in place that allow unsecured communication on the port used (KDNET does not talk IPSec).

The Debugger Window will now look like this:

The Debugger is now set up and ready to go.

Reboot the target system now.

When the target comes back online, it will try to connect to the IP Address and Port that was configured with the bcdedit.exe command. The Debugger Command Window will look something like the screenshot below.

You now can break in as usual. This is a good time to fix your symbol setup if you have not done it yet.

Operation

You still can communicate normally over the NIC and IP that you use on the target. You do not need an additional NIC in the target to use KDNET. When debugging production servers with heavy traffic, we recommend using a dedicated NIC for debugging (note, 10GigE NICs are currently not supported).

If you don’t want the NIC to be used by the OS as well, it can be disabled via: bcdedit.exe -set loadoptions NO_KDNIC

Although you can use KDNET to debug power state transitions (in particular Connected Standby), it is best avoided. The KDNET protocol polls on a regular basis and as such, many systems will not drop to a lower power state. Instead, use USB, 1394, or serial.

Disconnecting the NIC from media (unplugging the NIC in the target machine) is not supported and will most likely blue screen the target machine.

Note 1:

If you have more than one NIC in your target, please read the following (copied from the debugger help):

If there is more than one network adapter in the target computer, use Device Manager to determine the PCI bus, device, and function numbers for the adapter you want to use for debugging. Then in an elevated Command Prompt window, enter the following command, where b, d, and f are the bus number, device number, and function number of the adapter:

bcdedit /set {dbgsettings} busparams b.d.f

Note 2:

If you use the Windows NIC Teaming (LBFO) in Server 2012: KDNET is not compatible with NIC Teaming as indicated by the Whitepaper:

http://download.microsoft.com/download/F/6/5/F65196AA-2AB8-49A6-A427-373647880534/[Windows%20Server%202012%20NIC%20Teaming%20(LBFO)%20Deployment%20and%20Management].docx

How does it look on the network?

This is a packet sent from the target to the debug host machine.

The TTL of the packets sent from the target to the debug host is currently set to 16 (this is not configurable).

This screenshot shows that your connection can only run over 16 IP hops max. This is a theoretical limitation, but it highlights some important facts. Your host is not talking to the Windows IP stack on the target, instead it talks to a basic IPv4/UDP implementation in KDNET. The transport is UDP/IPv4 based, so there is not much tolerance for poor network conditions aside from retry operations at the Debugger Transport Protocol Level.

A few words on performance.

The performance is generally limited by the latency of the link between the host and target. Therefore, even with a LAN like latency (<=1ms), you will not be able to get even close to wire speed of a 1GigE Connection. Expect to see speeds between 1.5 – 2.5Mbytes/s.

Keep this in mind when you plan to pull large portions of memory from the target over KDNET (like the .dump command). This screenshot was taken while executing the .dump /f command (Full Kernel Dump):

Even with the performance restrictions mentioned, KDNET is a valuable extension of the existing debugging methods. It allows you to debug a Windows machine without the need for special hardware (1394) or legacy ports (serial) that not every machine has today (especially tablets and notebooks). It also saves you from using USB2 debugging - which requires special cables and a good amount of hope that the machine’s vendor has attached the single debug capable USB port to an external port on the chassis.

Also, there is no need for you to physically enter the Datacenter where the target is located. You can do all these steps from your convenient office chair. J

To see network kernel debugging in action, watch Episode #27 of Defrag Tools on Channel 9.

Thanks to Andrew Richards and Joe Ballantyne for their help in writing this article.

Our Bangalore Team is Hiring - Windows Server Escalation Engineer

ntdebug — Thu, 09 May 2013 22:32:46 GMT

Would you like to join the world’s best and most elite debuggers to enable the success of Microsoft solutions?

As a trusted advisor to our top customers you will be working with to the most experienced IT professionals and developers in the industry. You will influence our product teams in sustained engineering efforts to drive improvements in our products.

This role involves deep analysis of product source code and debugging to solve problems in multi-million dollar configurations and will give you an opportunity to stretch your critical thinking skills. During the course of debugging, you will uncover opportunities to improve the customer experience while influencing the current and future design of our products.

In addition to providing support to customers while being the primary interface to our sustained engineering teams, you will also have the opportunity to work with new technologies and unreleased software. Through our continuous investment in depth training and hands-on experience with tough customer challenges you will become the world’s best in this area. Expect to partner with many various roles at Microsoft launching a very successful career!

This position is located is at the Microsoft Global Technical Support Center in Bangalore, India.

Learn more about what an Escalation Engineer does at:

Profile: Ron Stock, CTS Escalation Engineer - Microsoft Customer Service & Support - What is CSS?

Microsoft JobsBlog JobCast with Escalation Engineer Jeff Dailey

Microsoft JobsBlog JobCast with Escalation Engineer Scott Oseychik

Apply here:

https://careers.microsoft.com/jobdetails.aspx?ss=&pg=0&so=&rw=1&jid=109989&jlang=en&pp=ss

Interpreting Event 153 Errors

ntdebug — Tue, 30 Apr 2013 22:55:28 GMT

Hello my name is Bob Golding and I would like to share with you a new event that you may see in the system event log. Event ID 153 is an error associated with the storage subsystem. This event was new in Windows 8 and Windows Server 2012 and was added to Windows 7 and Windows Server 2008 R2 starting with hot fix KB2819485.

An event 153 is similar to an event 129. An event 129 is logged when the storport driver times out a request to the disk; I described event 129 messages in a previous article. The difference between a 153 and a 129 is that a 129 is logged when storport times out a request, a 153 is logged when the storport miniport driver times out a request. The miniport driver may also be referred to as an adapter driver or HBA driver, this driver is typically written the hardware vendor.

Because the miniport driver has a better knowledge of the request execution environment, some miniport drivers time the request themselves instead of letting storport handle request timing. This is because the miniport driver can abort the individual request and return an error rather than storport resetting the drive after a timeout. Resetting the drive is disruptive to the I/O subsystem and may not be necessary if only one request has timed out. The error returned from the miniport driver is bubbled up to the class driver who can log an event 153 and retry the request.

Below is an example event 153:

This error means that a request failed and was retried by the class driver. In the past no message would be logged in this situation because storport did not timeout the request. The lack of messages resulted in confusion when troubleshooting disk errors because timeouts would occur but there would be no evidence of the error.

The details section of the event the log record will present what error caused the retry and whether the request was a read or write. Below is the details output:

In the example above at byte offset 29 is the SCSI status, at offset 30 is the SRB status that caused the retry, and at offset 31 is the SCSI command that is being retried. In this case the SCSI status was 00 (SCSISTAT_GOOD), the SRB status was 09 (SRB_STATUS_TIMEOUT), and the command was 28 (SCSIOP_READ).

The most common SCSI commands are:

SCSIOP_READ - 0x28

SCSIOP_WRITE - 0x2A

The most common SRB statuses are below:

SRB_STATUS_TIMEOUT - 0x09

SRB_STATUS_BUS_RESET - 0x0E

SRB_STATUS_COMMAND_TIMEOUT - 0x0B

A complete list of SCSI operations and statuses can be found in scsi.h in the WDK. A list of SRB statuses can be found in srb.h.

The timeout errors (SRB_STATUS_TIMEOUT and SRB_STATUS_COMMAND_TIMEOUT) indicate a request timed out in the adapter. In other words a request was sent to the drive and there was no response within the timeout period. The bus reset error (SRB_STATUS_BUS_RESET) indicates that the device was reset and that the request is being retried due to the reset since all outstanding requests are aborted when a drive receives a reset.

A system administrator who encounters event 153 errors should investigate the health of the computer’s disk subsystem. Although an occasional timeout may be part of the normal operation of a system, the frequent need to retry requests indicates a performance issue with the storage that should be corrected.

Commitment Failures, Not Just a Failed Love Story

ntdebug — Tue, 16 Apr 2013 20:21:14 GMT

I was working on a debug the other day when I ran the “!vm” command and saw that the system had some 48,000 commit requests that failed. This was strange as the system was not out of memory and the page file was not full. I was left scratching my head and thinking “I wish I knew where !vm got that information from.” So I went on a quest to find out, here is what I found.

13: kd> !vm 1

*** Virtual Memory Usage ***

Physical Memory: 12580300 ( 50321200 Kb)

Page File: \??\C:\pagefile.sys

Current: 50331648 Kb Free Space: 50306732 Kb

Minimum: 50331648 Kb Maximum: 50331648 Kb

Available Pages: 4606721 ( 18426884 Kb)

ResAvail Pages: 12189247 ( 48756988 Kb)

Locked IO Pages: 0 ( 0 Kb)

Free System PTEs: 33460257 ( 133841028 Kb)

Modified Pages: 20299 ( 81196 Kb)

Modified PF Pages: 6154 ( 24616 Kb)

NonPagedPool 0 Used: 19544 ( 78176 Kb)

NonPagedPool 1 Used: 22308 ( 89232 Kb)

NonPagedPool Usage: 53108 ( 212432 Kb)

NonPagedPool Max: 9408956 ( 37635824 Kb)

PagedPool 0 Usage: 168921 ( 675684 Kb)

PagedPool 1 Usage: 4149241 ( 16596964 Kb)

PagedPool 2 Usage: 17908 ( 71632 Kb)

PagedPool Usage: 4336070 ( 17344280 Kb)

PagedPool Maximum: 33554432 ( 134217728 Kb)

Session Commit: 3438 ( 13752 Kb)

Shared Commit: 6522 ( 26088 Kb)

Special Pool: 0 ( 0 Kb)

Shared Process: 53597 ( 214388 Kb)

PagedPool Commit: 4336140 ( 17344560 Kb)

Driver Commit: 5691 ( 22764 Kb)

Committed pages: 5565215 ( 22260860 Kb)

Commit limit: 25162749 ( 100650996 Kb)

********** 48440 commit requests have failed **********

It turns out that this calculation is from a global ULONG array named “nt!MiChargeCommitmentFailures”. The array has 4 members and they are used to trace the types of commit failures that have taken place. This is done by first calculating the new commit size NewCommitValue = CurrentCommitValue + SystemReservedMemory. Based on this calculation commit errors are tracked in a few different ways, which are listed below with the corresponding member in the array that is incremented.

MiChargeCommitmentFailures[0] - If the system failed a commit request and an expansion of the pagefile has failed.

MiChargeCommitmentFailures[1] - If the system failed a commit and we have already reached the maximum pagefile size.

MiChargeCommitmentFailures[2] - If the system failed a commit while the pagefile lock is held.

MiChargeCommitmentFailures[3] - If the system failed a commit and the NewCommitValue is less than or equal to CurrentCommitValue.

In order to calculate the count of failures, "!vm" adds up the values stored in each array member of the array. Members 0 and 1 are always counted, member 2 is counted if the OS version is Windows 2003/XP and member 3 is counted if the build version is newer than Windows 2003/XP.

Let's look at the array in the dump I was debugging:

13: kd> dc nt!MiChargeCommitmentFailures L4

fffff800`01e45ce0 00000000 0000bd38 00000000 00000000 ....8...........

Converting this to decimal we find the 48000+ commit failures I was seeing the in output of !VM.

13: kd> ?0000bd38

Evaluate expression: 48440 = 00000000`0000bd38

Since I now had my answer, “where does the number come from?”, I was left wanting to know a bit more about the overall flow of why a VirtualAlloc fails to commit.

When memory is allocated by VirtualAlloc the newly allocated memory is not committed to physical memory. Only when the memory is accessed by a read or write is it backed by physical memory.

When this newly allocated memory is accessed for the first time it will need to be backed by commit space. Under normal conditions this is a smooth process, however when the system hits what’s called the commit limit and can’t expand this limit we see commit failures.

So how is the commit limit calculated? Let’s say we have a system with 4GB of physical memory and a pagefile that is 6GB in size. To determine the commit limit we add physical memory and the pagefile size together - in this example the commit limit would be 10GB. Since memory manger will not let any user mode allocation consume every last morsel of commit space it keeps a small amount of the commit space for the system to avoid hangs. When the limit is reached the system tries to grow the page file. If there is no more room to grow the pagefile or the pagefile has reached its configured maximum size, the system will try and free some committed memory to make room for more requests. If expansion of the page file or the attempt to free memory do not allow the allocation to complete, the allocation fails and MiChargeCommitmentFailures is incremented.

To sum it all up, commit limit is RAM + pagefile, commit failures happen when we hit the commit limit and the system is unable to grow the pagefile because it is already at its max. It’s that simple, well almost.

For those that will want to know more about how memory manger works please see the post from Somak: The Memory Shell Game.

Randy Monteleone

Debugging a Network Connectivity Issue - TrackNblOwner to the Rescue

ntdebug — Fri, 29 Mar 2013 21:59:23 GMT

Hello Debug community this is Karim Elsaid again. Today I’m going to discuss a recent interesting case where intermittently the server is losing access to the network. No communication (even pings) can be done from / to the server when the issue hits.

We went through the normal exercise and asked the customer to obtain a Kernel memory dump from the machine while it was in the problematic state, hoping that we will find some data to help us to demystify the issue.

One of the very first commands we run upon receiving a hang dump is the very famous “!locks” command. This yielded the following:

8: kd> !locks

**** DUMP OF ALL RESOURCE OBJECTS ****

KD: Scanning for held locks..

Resource @ nt!IopDeviceTreeLock (0xfffff80001a81c80) Shared 1 owning threads

Threads: fffffa800cd8a040-01<*>

KD: Scanning for held locks.

Resource @ nt!PiEngineLock (0xfffff80001a81b80) Exclusively owned

Contention Count = 6

Threads: fffffa800cd8a040-01<*>

KD: Scanning for held locks

84372 total locks, 2 locks currently held

What I’m looking for is Locks with exclusive owners and waiters. From the above output we can see that thread fffffa800cd8a040 exclusively owns a Plug and Play (Pi prefix) lock and shared owns an I/O Manager (Io prefix) device tree lock.

There are no waiters for the exclusive lock, however PnP locks always worth investigating. While debugging I always treat everything a possible suspect unless proven otherwise, so let’s dump this thread:

8: kd> !thread fffffa800cd8a040 e

THREAD fffffa800cd8a040 Cid 0004.005c Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable

fffff88002b0f118 SynchronizationEvent

IRP List:

fffffa8016527510: (0006,0310) Flags: 00000000 Mdl: 00000000

Not impersonating

DeviceMap fffff8a000006100

Owning Process fffffa800cd56040 Image: System

Attached Process N/A Image: N/A

Wait Start TickCount 14791337 Ticks: 15577 (0:00:04:03.002)

Context Switch Count 835317 IdealProcessor: 2

UserTime 00:00:00.000

KernelTime 00:00:26.863

Win32 Start Address nt!ExpWorkerThread (0xfffff8000188f530)

Stack Init fffff88002b0fc70 Current fffff88002b0ee30

Base fffff88002b10000 Limit fffff88002b0a000 Call 0

Priority 12 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5

*** ERROR: Module load completed but symbols could not be loaded for myfault.sys

Child-SP RetAddr Call Site

fffff880`02b0ee70 fffff800`0187ba32 nt!KiSwapContext+0x7a

fffff880`02b0efb0 fffff800`0188cd8f nt!KiCommitThreadWait+0x1d2

fffff880`02b0f040 fffff800`018e1816 nt!KeWaitForSingleObject+0x19f

fffff880`02b0f0e0 fffff880`01618fcd nt! ??::FNODOBFM::`string'+0x12ff6

fffff880`02b0f150 fffff880`0173f54e tcpip!FlPnpEvent+0x17d

fffff880`02b0f1c0 fffff880`00f87b2f tcpip!Fl48PnpEvent+0xe

fffff880`02b0f1f0 fffff880`00f884b7 NDIS!ndisPnPNotifyBinding+0xbf

fffff880`02b0f280 fffff880`00fa1911 NDIS!ndisPnPNotifyAllTransports+0x377

fffff880`02b0f3f0 fffff880`00fa2c5b NDIS!ndisCloseMiniportBindings+0x111

fffff880`02b0f500 fffff880`00f3bbc2 NDIS!ndisPnPRemoveDevice+0x25b

fffff880`02b0f6a0 fffff880`00fa5b69 NDIS!ndisPnPRemoveDeviceEx+0xa2

fffff880`02b0f6e0 fffff800`01aec8d9 NDIS!ndisPnPDispatch+0x609

fffff880`02b0f780 fffff800`01c6c1e1 nt!IopSynchronousCall+0xc5

fffff880`02b0f7f0 fffff800`0197f733 nt!IopRemoveDevice+0x101

fffff880`02b0f8b0 fffff800`01c6bd34 nt!PnpRemoveLockedDeviceNode+0x1a3

fffff880`02b0f900 fffff800`01c6be40 nt!PnpDeleteLockedDeviceNode+0x44

fffff880`02b0f930 fffff800`01cfcd04 nt!PnpDeleteLockedDeviceNodes+0xa0

fffff880`02b0f9a0 fffff800`01cfd35c nt!PnpProcessQueryRemoveAndEject+0xc34

fffff880`02b0fae0 fffff800`01be65ce nt!PnpProcessTargetDeviceEvent+0x4c

fffff880`02b0fb10 fffff800`0188f641 nt! ?? ::NNGAKEGL::`string'+0x5ab9b

fffff880`02b0fb70 fffff800`01b1ce5a nt!ExpWorkerThread+0x111

fffff880`02b0fc00 fffff800`01876d26 nt!PspSystemThreadStartup+0x5a

fffff880`02b0fc40 00000000`00000000 nt!KiStartSystemThread+0x16

Interesting, by looking at the stack above we can see that thread is doing some NDIS PnP stuff. This thread has been waiting for more than 4 minutes, but hold on, what is “ nt! ?? ::FNODOBFM::`string”? This doesn’t seem to be a useful function name, no its not! This is a side effect of Basic Block Tools optimization (BBT). Using public symbols the debugger will find it hard to get to the right symbol, there is a nice a trick you can use in order to get to the right function.

P.S for a nice x64 Deep Dive please refer to our archive.

Let’s display the function data for the return address fffff800`018e1816:

8: kd> .fnent fffff800`018e1816

Debugger function entry 000000e8`f28f14f8 for:

(fffff800`018c4790) nt! ?? ::FNODOBFM::`string'+0x12ff6 | (fffff800`018c47c8) nt!vDbgPrintExWithPrefixInternal

BeginAddress = 00000000`000da7d0

EndAddress = 00000000`000da81c

UnwindInfoAddress = 00000000`001c8a54

Unwind info at fffff800`019cfa54, 10 bytes

version 1, flags 4, prolog 0, codes 0

Chained info:

BeginAddress = 00000000`000182f0

EndAddress = 00000000`00018358

UnwindInfoAddress = 00000000`001bf910

Unwind info at fffff800`019c6910, 6 bytes

version 1, flags 0, prolog 4, codes 1

00: offs 4, unwind op 2, op info c UWOP_ALLOC_SMALL.

For optimized binaries, you will find a section “Chained Info”. Add the BeginAddress to the start address of the module and you should hit the correct function so:

8: kd> ln nt+000182f0

(fffff800`0181f2f0) nt!ExWaitForRundownProtectionReleaseCacheAware | (fffff800`0181f358) nt!KeGetRecommendedSharedDataAlignment

Exact matches:

nt!ExWaitForRundownProtectionReleaseCacheAware (<no parameter info>)

Bingo! You got the function. So tcpip!FlPnpEvent was calling ExWaitForRundownProtectionReleaseCacheAware. This function will basically wait for the rundown protection to drop down to 0.

A thread can call ExAcquireRundownProtectionEx against a shared object for safe access. Rundown Protection provides a way to protect an object from being deleted unless all outstanding access has been finished (Run Down). The “ExWaitForRundownProtectionReleaseCacheAware” will do exactly the same; it will wait for all rundown protection calls to be completed.

The question is which structure are we waiting for its rundown to drain, that will depend on what we are dealing with. Because of code optimization the debugger is not showing you the full picture. Through code review I found that in this particular dump there is an inline call to function “FlpUninitializePacketProviderInterface”.

So the stack in reality should look like this:

Child-SP RetAddr Call Site

fffff880`02b0ee70 fffff800`0187ba32 nt!KiSwapContext+0x7a

fffff880`02b0efb0 fffff800`0188cd8f nt!KiCommitThreadWait+0x1d2

fffff880`02b0f040 fffff800`018e1816 nt!KeWaitForSingleObject+0x19f

fffff880`02b0f0e0 fffff880`01618fcd nt!ExWaitForRundownProtectionReleaseCacheAware

----inline function---- tcpip!FlpUninitializePacketProviderInterface

fffff880`02b0f150 fffff880`0173f54e tcpip!FlPnpEvent+0x17d

fffff880`02b0f1c0 fffff880`00f87b2f tcpip!Fl48PnpEvent+0xe

…

So we need to un-initialize a network interface but before doing that we need to make sure that there are no outstanding references to packets and that there are no outstanding packets pending. When we say packets, starting in NDIS 6 we basically mean “NET_BUFFER” and “Net_Buffer_List” structures. So we need to check for any outstanding Net_Buffer_Lists (NBLs) that are pending, one reference will correspond to one pending NBL.

To the rescue, the “NDISKD” debugger extension has a very nice and handy command to display all pending NBLS and their owners, it is “!pendingnbls”. For the command to work it you must first enable “TrackNblOwner” through the registry. By default, this registry key is not enabled on server SKUs as it may cause a performance hit. On client SKUs this is enabled by default.

When you run !pendingnbls on a clean Windows 2008 R2 install you get:

8: kd> !ndiskd.pendingnbls

This command requires NBL tracking to be enabled on the debugee target

machine. (By default, client operating systems have level 1, and servers

have level 0). To enable, set this REG_DWORD value to a nonzero value on

the target machine and reboot the target machine:

HKLM\SYSTEM\CurrentControlSet\Services\NDIS\Parameters ! TrackNblOwner

Possible Values (features are cumulative)

* 0: Disable all tracking.

* 1: Track the most recent owner of each NBL (enables !ndiskd.pendingnbls)

Show me all allocated NBLs so I can manually find the one I want

You can find all allocated NBLs with the command “!ndiskd.nblpool -force -find ((@$extin.Flags)&0x108)==0x100)”, but still you don’t get any owner.

So I asked the customer to turn on “TrackNblOwner” and reboot, wait for the next occurrence of the issue and get a new memory dump.

Two days later we received the memory dump file. I verified that they are having the same issue I found in the last dump and that TrackNblOwner is configured correctly:

23: kd> dp NDIS!ndisTrackNblOwner L1

fffff880`00ef1a30 00000000`00000001

Then I immediately checked all pending NBLs to claim the prize, and it was not surprising to see why the NIC card was not un-initializing:

23: kd> !ndiskd.pendingnbls

PHASE 1/3: Found 20 NBL pool(s).

PHASE 2/3: Found 550 freed NBL(s).

Pending Nbl Currently held by

fffffa801dc559f0 fffffa80142d31a0 - My Ethernet 1Gb 4-port Adapter [Miniport]

fffffa801dc81680 fffffa80142d31a0 - My Ethernet 1Gb 4-port Adapter [Miniport]

fffffa80131d2aa0 fffffa80142d31a0 - My Ethernet 1Gb 4-port Adapter [Miniport]

……………………………….

Ret of the repeated output omitted

PHASE 3/3: Found 1854 pending NBL(s) of 3005 total NBL(s).

Search complete.

So we currently have 1854 NBLs pending on the NIC miniport driver “fffffa80142d31a0”. This is the Miniport that currently holding all NBLs:

23: kd> !ndiskd.miniport fffffa80142d31a0

MINIPORT

My Ethernet 1Gb 4-port Adapter

Ndis handle fffffa80142d31a0

Ndis API version v6.20

Adapter context fffffa80138cc000

Miniport driver fffffa800d4f7530 - MyMiniPortDriver v1.0

Network interface fffffa800d25e870

Media type 802.3

Device instance PCI\VEN_1111&DEV_1111&SUBSYS_169D103C&REV_01\4&2263a140&0&0010

Device object fffffa80142d3050 More information

MAC address xx-xx-xx-xx-xx-xx

STATE

Miniport Running

Device PnP QUERY_REMOVED

Datapath Normal

Operational status DORMANT

Operational flags DORMANT_PAUSED

Admin status ADMIN_UP

Media Connected

Power D0

References 9

Total resets 0

Pending OID None

Flags BUS_MASTER, 64BIT_DMA, SG_DMA, DEFAULT_PORT_ACTIVATED,

SUPPORTS_MEDIA_SENSE, DOES_NOT_DO_LOOPBACK,

MEDIA_CONNECTED

PnP flags PM_SUPPORTED, DEVICE_POWER_ENABLED, RECEIVED_START,

HARDWARE_DEVICE

…

What you notice from the above that the device received a “Query_Removed” PNP and is currently in a Dormant_Paused state.

From: http://msdn.microsoft.com/en-us/library/ff566737.aspx:

NET_IF_OPER_STATUS_DORMANT_PAUSED

The operational status is set to NET_IF_OPER_STATUS_DORMANT because the miniport adapter is in the paused or pausing state.

NDIS 6.0 and up allow miniport adapters to be paused and the documentation here shows what the miniport driver should do when it receives a pause request.

Because the adapter was in a pause state, basic network commads like “ping” ceased to work as described earlier in the symptoms. The next action is definitely to involve the miniport adapter vendor to trace this further and find out why all these pending NBLs were not completed.

Until a next adventure!

Best Regards,

Karim

Understanding File System Minifilter and Legacy Filter Load Order

ntdebug — Mon, 25 Mar 2013 23:39:57 GMT

Hello, my name is Fred Jeng from the Global Escalation Services team. For today’s post, I want to go over how Windows 7 and Windows Server 2008 R2 load file system mini-filters in a mixed environment when legacy filters are also present. I recently came across an issue where the filters were being loaded out of order based on their altitudes. This can cause all sorts of problems with a filter driver’s functionality if they are incorrectly positioned on the stack. Take for example the following filter stack, obtained using the fltmc command from the cmd prompt:

C:\Windows\system32>fltmc

Filter Name Num Instances Altitude Frame

------------------------------ ------------- ------------ -----

AVLegacy 389998.99 <Legacy>

EncryptionLegacy 149998.99 <Legacy>

AVMiniFilter 3 328000 0

luafv 1 135000 0

FileInfo 13 45000 0

At first glance it looks like there is a problem causing the legacy encryption filter to be loaded above the antivirus minifilter, which has a higher altitude. This may cause issues with AVMiniFilter as the IOs that it receives are still encrypted. Due to limitations in how the filter drivers attach to the driver stack, this is actually the intended behavior. However, there is a solution to manipulate the load order to load the legacy filters correctly based on their altitude.

First some background information regarding legacy filters and minifilters.

In the old days before minifilters, legacy drivers can only attach at the top of the driver stack so the load order also controlled the attachment order. The earlier a legacy driver loads, the lower it can attach on the file system stack. Minifilters on the other hand can load at any time, but their positions relative to other minifilters are controlled by their altitude. When a minifilter loads, it needs to register with an appropriate frame created by fltmgr. Each frame is a fltmgr device object and represents a range of altitudes. There can be more than one frame on the file system stack but the range of altitudes that each frame represents cannot overlap with the altitude range of another frame. For interoperability with legacy drivers, minifilters must still maintain a load order group. The frames are created and managed by fltmgr, which itself is a legacy driver. The ramification of this is that fltmgr must follow the old legacy filter driver rules and attach only at the top of the stack.

From the above example, let’s walk through how the legacy and minifilters above are loaded to get us into the state such that the altitude appears to be out of order.

First, here are the details for the 5 drivers.

Driver Name	Type	Load Order	Start Type	Altitude
AVLegacy	Legacy	FsFilter Anti-Virus	SERVICE_BOOT_START	329998.99
AVMiniFilter	Minifilter	FsFilter Anti-Virus	SERVICE_BOOT_START	328000
EncryptionLegacy	Legacy	FsFilter Encryption	SERVICE_BOOT_START	149998.99
Luafv	Minifilter	FsFilter Virtualization	SERVICE_AUTO_START	135000
FileInfo	Minifilter	FSFilter Bottom	SERVICE_BOOT_START	45000

MSDN has an article that describes load order groups and altitudes for minifilters: http://msdn.microsoft.com/en-us/library/windows/hardware/ff549689%28v=vs.85%29.aspx.

Referencing this article regarding load order groups and altitudes for minifilter drivers, we can determine that our filters will load in the following order.

FileInfo

EncryptionLegacy

AVLegacy

AVMiniFilter

luafv

On system bootup, when fltmgr.sys loads it will create Frame 0 with a default altitude range of 0 to 49999. When FileInfo loads with an altitude of 45000, it will fit into the default Frame 0. Next to load is EncryptionLegacy. Since this is a legacy driver, it will attach on top of the legacy driver fltmgr.sys. So this is how our file system stack looks right now.

Next up is the AVLegacy driver. This is a legacy driver, so it has to attach above EncryptionLegacy.

Now the AVMinifilter will load with an altitude of 328000. The OS will check if it will fit in the Frame 0 Fltmgr, but this frame only supports an altitude of 0-45000. Before deciding to create a new fltmgr Frame instance, it will check if there are any legacy filters attached above Frame 0 and adjust Frame 0’s altitude if there are. So in our case, we do have legacy filters on the file system stack at this point and so we go up the list of legacy drivers. First we see EncryptionLegacy with an altitude of 149998.99 so we adjust Frame 0 to cover from 0 to 149998.99. We continue up the list and see AVLegacy with an altitude of 329998.99 so we again adjust the altitude of Frame 0 to now cover 0-329998.99. The reason we do this is because Frame 0 now must handle all minifilters below 329998.99. Since we can only attach legacy filters to the top of the stack, if we add an additional FltMgr frame instance, it has to sit above AVLegacy and can only support minifilters with altitude of 329998.99 or higher. Now that Frame 0 supports 0-329998.99, we can register AVMinifilter with Frame 0.

At this point, you can already see that AVMinifilter which has a higher altitude then EncryptionLegacy will be loaded below EncryptionLegacy. The last driver to load is the luafv minifilter, and it will fit into Frame 0.

A couple of things to point out.

Why can’t we insert a Frame between AVLegacy and EncryptionLegacy when ACMinifilter loads?

This is due to how the file system stack is constructed with legacy drivers only being able to attach to the top of the stack. Since FltMgr is a legacy driver, it has to conform to these rules.

Why do we adjust the altitude in Frame 0 to cover 0-329998.99? Why not stop at 149998.99?

If Frame 0 only adjusts its altitude to the legacy filter directly attached above it and not all the way to the highest attached legacy filter, we won’t be able to handle some range of mini-filters. For example, assume we only adjust Frame 0 to cover 0-149998.99, then when the AVMinifilter with an altitude of 328000 comes along, it won’t fit in Frame 0, and we’re unable to insert a Frame between AVLegacy (329998.99) and EncryptionLegacy(149998.99) so we would either be unable to load AVMinifilter, or we would have to create Frame 1 above AVLegacy and load AVMinifilter there. In which case we would again be faced with the altitude disordering issue.

If this is the expected behavior, how do we resolve the problem of EncryptionLegacy being loaded above AVMinifilter? The solution is to inject a dummy minifilter that loads at the appropriate time to force fltmgr to create a Frame between the legacy filters. For our case above, I used the DDK to create the NullFilter minifilter driver and changed the load order to FSFilter Compression and gave it an altitude of 160030 which is within the assigned altitude for FSFilterCompression and set the start type to SERVICE_BOOT_START. Please note that I only used this driver in a test environment, production minfilter drivers must use an altitude assigned by Microsoft.

For information on minifilter load order groups and altitude, reference http://msdn.microsoft.com/en-us/windows/hardware/gg462963.aspx.

Our list of filters are as follows:

Driver Name	Type	Load Order	Start Type	Altitude
AVLegacy	Legacy	FsFilter Anti-Virus	SERVICE_BOOT_START	329998.99
AVMiniFilter	Minifilter	FsFilter Anti-Virus	SERVICE_BOOT_START	328000
EncryptionLegacy	Legacy	FsFilter Encryption	SERVICE_BOOT_START	149998.99
Luafv	Minifilter	FsFilter Virtualization	SERVICE_AUTO_START	135000
FileInfo	Minifilter	FSFilter Bottom	SERVICE_BOOT_START	45000
NullFilter	Minifilter	FSFilter Compression	SERVICE_BOOT_START	160030

So with the new NullFilter dummy driver, our filter load order should be as follows:

FileInfo

EncryptionLegacy

NullFilter

AVLegacy

AVMiniFilter

luafv

After FileInfo and EncryptionLegacy loads, the stack is the same as what we had earlier.

Now when the NullFilter minifilter loads with an altitude of 160030, we see that it doesn’t fit in Frame 0. As before, we check for any attached legacy filter drivers and see EncryptionLegacy so we adjust Frame 0 to cover 0-149998.99. Since NullFilter still does not fit in Frame 0, we will create a new Frame and attach it above the EncryptionLegacy driver.

The AVLegacy driver will load next, and since it is a legacy driver, it will attach above the Frame 1 instance of FltMgr.

The last two minifilters to load are AVMiniFilter and luafv. When AVMinifilter loads into Frame 1 with an altitude of 328000, it will see that Frame 1 at the time only supports 149998.99-160030. It follows the same algorithm to check if there are any legacy filters attached above the frame. In this case, we have AVLegacy attached above Frame 1 so we adjust Frame 1 to cover 149998.99-329998.99 before inserting AVMinifilter into Frame 1.

By strategically injecting a dummy minifilter driver, we can get the legacy and minifilter drivers to all load at the correct altitude.

Don't Believe Everything You Read

ntdebug — Wed, 06 Mar 2013 23:08:51 GMT

Recently, I was contacted by a customer who was advised by an ISV to set a registry value under one of the sub keys in HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\. Let's call it UseQuantumComputing = 1 (value name has been changed to protect the ISV). The customer wanted to know what this value actually did and no one could find any documentation explaining it. These issues often come to our team because we have access to the Windows source code. I did a bit of code review to find out what this value does. As it turns out, nowhere in Windows source code between Windows 2000 and Windows Server 2012 do we ever check for or set UseQuantumComputing.

I can think of a few reasons the ISV would suggest setting this value. Perhaps they were under the impression this did something but got confused about the value name. It's possible they hoped making a registry change would have a placebo effect. Or, perhaps their software actually checks this value, not Windows.

The latter of these possibilities is probably the worst case scenario. An ISV should not create a registry value inside of keys used for Windows’ own internal use. Why? The first reason is that there's no guarantee that Microsoft won't end up coincidentally using that same value name later. This would cause a conflict between the two users of the value. Second, we have to consider the scenario where two different ISVs both decide to use the same value. That would be bad too. Lastly, there's no guarantee that the key in use will still exist in later versions, or that it will be writeable or readable by the ISV due to permission changes. In addition to all these reasons, there is the common sense issue that it is just confusing. Now the ISV's software and uninstaller needs to look all over the registry, not just in their own keys.

On a similar note, I also recently had a case where a "Windows Tips" blog (not created, endorsed, or run by Microsoft) suggested using a registry value that was implemented in Windows but was not documented by Microsoft. It turns out this value wasn't thoroughly tested (because it was undocumented and wasn't intended to be used in production), and using it would cause server hangs under certain conditions. These hangs were only discovered after a large customer decided to implement the undocumented value across their enterprise.

Here are a few tips for IT Pros, developers, and users alike:

Don't implement random registry settings if you can't find documentation for that setting on an official Microsoft site, like MSDN, TechNet, or support.microsoft.com(information on forums or answer boards (e.g. social.*.microsoft.com or answers.*.microsoft.com) is not official documentation). At best these unknown registry settings they will do nothing, at worst they will cause you headaches later.
If a key/value isn't documented, changes to it likely are not tested, and could put your machine in a state that makes it difficult or impossible to support.
If you are a developer, keep any of your registry settings in your own key. Don't pollute in others' keys.
If an ISV or Microsoft suggests you implement a setting, make sure you understand the implications of that setting.

I'll leave you with the warning displayed in many of our KBs - it's there for a reason!

WARNING: If you use Registry Editor incorrectly, you may cause serious problems that may require you to reinstall your operating system. Microsoft cannot guarantee that you can solve problems that result from using Registry Editor incorrectly. Use Registry Editor at your own risk.

-Matt

Leaving the Do Not Disturb Sign on the Door Will Cause the KERNEL_APC_PENDING_DURING_EXIT Bugcheck

ntdebug — Fri, 01 Mar 2013 01:12:12 GMT

This is Ron Stock from the Global Escalation Services team and I recently worked with a customer to determine which misbehaving driver was crashing their critical server. This particular crash was a STOP 0x00000020 which maps to KERNEL_APC_PENDING_DURING_EXIT.

The KERNEL_APC_PENDING_DURING_EXIT bugcheck type indicates the APC disable count for a thread was not equal to zero when the thread exited. The APC disable count is a field in the _KTHREAD structure and it is decremented when drivers disable APCs by calling functions such as KeEnterCriticalRegion, FsRtlEnterFileSystem or by acquiring a mutex. Disabling APC delivery to a thread is the equivalent of hanging the “Do Not Disturb” sign on your door. When drivers need to perform a critical operation they ‘hang the sign on the door’ to prevent interruption from APCs. When the same driver fails to ‘take the sign off the door’ by calling KeLeaveCriticalRegion, FsRtlExitFileSystem or KeReleaseMutex, the APC disable count is never incremented back to its original value. This forgetful behavior causes a bugcheck because the APC disable count is checked when the thread is exiting. The OS expects this value to be zero on thread exit.

In my case the value was 0xffff (negative 1) indicating a driver had forgot to remove the ‘Do Not Disturb’ sign.

kd> !analyze –v

KERNEL_APC_PENDING_DURING_EXIT (20)

The key data item is the thread's APC disable count.

If this is non-zero, then this is the source of the problem.

Arguments:

Arg1: 0000000000000000, The address of the APC found pending during exit.

Arg2: 000000000000ffff, The thread's APC disable count

Arg3: 0000000000000000, The current IRQL

Arg4: 0000000000000001

Because the value is decremented earlier in time the current call stack is not particularly useful. It merely shows the thread exiting under normal conditions.

0: kd> !thread -1 e

THREAD fffffa8049f04b50 Cid 0004.0998 Teb: 0000000000000000 Win32Thread: 0000000000000000 RUNNING on processor 0

Not impersonating

DeviceMap fffff8a000007ee0

Owning Process fffffa8048cad9e0 Image: System

Attached Process N/A Image: N/A

Wait Start TickCount 11503325 Ticks: 0

Context Switch Count 185715 IdealProcessor: 0

UserTime 00:00:00.000

KernelTime 00:00:06.078

Win32 Start Address srv2!SrvProcWorkerThread(0xfffff88003c4b400)

Stack Init fffff88005078db0 Current fffff880050789b0

Base fffff88005079000 Limit fffff88005073000 Call 0

Priority 15 BasePriority 15 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5

Child-SP RetAddr Call Site

fffff880`05078b08 fffff800`01984bd9 nt!KeBugCheckEx

fffff880`05078b10 fffff800`019a1a3d nt!PspExitThread+0xffffffff`fffe3ae9

fffff880`05078c10 fffff800`0195bc8a nt!PspTerminateThreadByPointer+0x4d

fffff880`05078c60 fffff880`03c56769 nt!PsTerminateSystemThread+0x22

fffff880`05078c90 fffff880`03c4b5b6 srv2!SrvProcTerminateWorkerThreadInternal+0x99

fffff880`05078cc0 fffff800`01966e5a srv2!SrvProcWorkerThread+0x1b6

fffff880`05078d40 fffff800`016c0d26 nt!PspSystemThreadStartup+0x5a

fffff880`05078d80 00000000`00000000 nt!KxStartSystemThread+0x16

Driver Verifier is the ideal tool for this type of bugcheck. It has a feature called Critical Region logging which tracks the call stack and KTRHEAD value for each call to either KeEnterCriticalRegion() and KeLeaveCriticalRegion(). I had the customer enable this logging by selecting the “Miscellaneous checks” option in Driver Verifier using these steps-

Run Verifier.exe
Select “Create custom settings (For code developers)”
Select individual settings from a full list
Select Miscellaneous checks
Select Driver Names from a list
Manually choose all of the third-party drivers.
Reboot after making the changes.

After running through the steps above, we gathered another STOP 0x00000020 dump. I confirmed the “Miscellaneous checks” option was enabled by using the !verifier command

0: kd> !verifier

Verify Level 800 ... enabled options are:

Miscellaneous checks enabled

The stack in this new dump was in the same SrvProcWorkerThread thread exit path so we had a consistent pattern. The thread with the negative APC Disable count was fffffa804b5be040.

0: kd> !thread -1 e

THREAD fffffa804b5be040 Cid 0004.082c Teb: 0000000000000000 Win32Thread: 0000000000000000 RUNNING on processor 0

Not impersonating

DeviceMap fffff8a000007ee0

Owning Process fffffa8048cad9e0 Image: System

Attached Process N/A Image: N/A

Wait Start TickCount 4458237 Ticks: 0

Context Switch Count 36067 IdealProcessor: 0

UserTime 00:00:00.000

KernelTime 00:00:01.218

Win32 Start Address srv2!SrvProcWorkerThread(0xfffff88004827400)

Stack Init fffff88005cc6db0 Current fffff88005cc69b0

Base fffff88005cc7000 Limit fffff88005cc1000 Call 0

Priority 15 BasePriority 15 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5

Child-SP RetAddr Call Site

fffff880`05cc6b08 fffff800`0198dbd9 nt!KeBugCheckEx

fffff880`05cc6b10 fffff800`019aaa3d nt!PspExitThread+0xffffffff`fffe3ae9

fffff880`05cc6c10 fffff800`01964c8a nt!PspTerminateThreadByPointer+0x4d

fffff880`05cc6c60 fffff880`048326d9 nt!PsTerminateSystemThread+0x22

fffff880`05cc6c90 fffff880`048275b6 srv2!SrvProcTerminateWorkerThreadInternal+0x99

fffff880`05cc6cc0 fffff800`0196fe5a srv2!SrvProcWorkerThread+0x1b6

fffff880`05cc6d40 fffff800`016c9d26 nt!PspSystemThreadStartup+0x5a

fffff880`05cc6d80 00000000`00000000 nt!KxStartSystemThread+0x16

I dumped the Critical Region log by using the !verifier 200 command. The Critical Region log has enough room for 128 stacks. After dumping the log, the first thing to do is to find the KTHREAD value of the thread with the non-zero APC disable count. Unfortunately in my case thread fffffa804b5be040 didn’t appear in the log. In fact all 128 stacks had a driver named Suspect.sys calling KeEnterCriticalRegion or KeLeaveCriticalRegion. Note: To protect our vendor friends, I renamed the actual sys file in this article to suspect.sys.

The customer disabled the suspect.sys driver hoping this was the driver forgetting to re-enable APCs. If nothing else, this would perhaps remove the noisy suspect.sys from the log in the next dump.

0: kd> !verifier 200

Enter/Leave Critical Region log:

There are up to 0x80 entries in the log.

Displaying all the log entries.

======================================================================

Thread fffffa8048ce4b50

fffff80001b74293 nt!VerifierKeLeaveCriticalRegion+0xc3

fffff8800100aafa Suspect.sys+0xaafa

fffff88001001e30 Suspect.sys+0x1e30

fffff80001abc68c nt!IopLoadUnloadDriver+0x1c

fffff800016e1641 nt!ExpWorkerThread+0x111

fffff8000196ee5a nt!PspSystemThreadStartup+0x5a

fffff800016c8d26 nt!KiStartSystemThread+0x16

======================================================================

Thread fffffa8048ce4b50

fffff80001b6b0a2 nt!VerifierKeEnterCriticalRegion+0x92

fffff880010062a3 Suspect.sys+0x62a3

fffff8800100a7e2 Suspect.sys+0xa7e2

fffff88001001e30 Suspect.sys+0x1e30

fffff80001abc68c nt!IopLoadUnloadDriver+0x1c

fffff800016e1641 nt!ExpWorkerThread+0x111

fffff8000196ee5a nt!PspSystemThreadStartup+0x5a

Unfortunately, the system continued to crash and in the next dump the critical region log was completely empty. My guess is the complier was optimizing the KeEnterCriticalRegion and KeLeaveCriticalRegion calls in the driver, causing them to be inlined and skipping the call to VerifierKeLeaveCriticalRegion/VerifierKeEnterCriticalRegion. I needed another attack plan.

There is another Verifier option called I/O Verification and it works in a similar way to the steps below. Please note that this functionality is not documented and may be subject to change at any time.

A call to IoCallDriver() is made to send an IO packet to a driver associated with a device.
Verifier hooks the call.
Verifier creates a structure to record state info.
Verifier fills in the structure with data including the thread’s APC Disable Count.
Next Verifier calls the normal IoCallDriver() routine to “continue” the call made in step 1.
The driver does its work (disables and re-enables APCs as needed)
The call to IoCallDriver() returns when the driver is finished.
Verifier checks the real APC count in the thread. Next it compares the value to the recorded value in the structure from step 4. If the two values do not match, then Verifier crashes the machine so we can pull the bad driver out of the dump.

I had the customer enable I/O Verification using these steps-

Run Verifier.exe
Select “Create custom settings (For code developers)”
Select individual settings from a full list
Select I/O Verification
Select Driver Names from a list
Manually choose all of the third-party drivers.
Reboot after making the changes.

As we expected, the machine crashed again because of the APC Disable issue. Because we enabled I/O Verification, the bugcheck type changed to DRIVER_VERIFIER_DETECTED_VIOLATION and now we have a smoking gun.

I used the !verifier command to review the Verifier settings. The output below shows “I\O subsystem checking enabled” which confirms I/O Verification was been enabled.

0: kd> !verifier

Verify Level 810 ... enabled options are:

Io subsystem checking enabled

The parameters to KeBugcheck reconfirmed the APC disable count was -1 (ffff). And this time we have an additional breadcrumb, the driver dispatch routine address.

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)

A device driver attempting to corrupt the system has been caught. This is

because the driver was specified in the registry as being suspect (by the

administrator) and the kernel has enabled substantial checking of this driver.

If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA will

be among the most commonly seen crashes.

Arguments:

Arg1: 00000000000000c5, Thread APC disable count changed by driver dispatch routine.

Arg2: fffff88001345610, Driver dispatch routine address.

Arg3: 000000000000ffff, Current thread APC disable count.

Arg4: 0000000000000000, Thread APC disable count before calling driver dispatch routine.

The APC disable count is decremented each time a driver calls

KeEnterCriticalRegion, FsRtlEnterFileSystem, or acquires a mutex. The APC

disable count is incremented each time a driver calls KeLeaveCriticalRegion,

FsRtlExitFileSystem, or KeReleaseMutex. Since these calls should always be in

pairs, this value should be zero when a thread exits. A negative value

indicates that a driver has disabled APC calls without re-enabling them. A

positive value indicates that the reverse is true.

Notice the Verifier functions on the call stack which we I leveraged for the “saved state” information I discussed above in the I/O Verification architecture.

0: kd> kn

# Child-SP RetAddr Call Site

00 fffff880`05db1b08 fffff800`0174a9c0 nt!KeBugCheckEx

01 fffff880`05db1b10 fffff800`01b66b4ent!VfBugCheckNoStackUsage+0x30

02 fffff880`05db1b50 fffff800`01b6cc2e nt!VfAfterCallDriver+0x33e

03 fffff880`05db1ba0 fffff880`04054756 nt!IovCallDriver+0x57e

04 fffff880`05db1c00 fffff880`0404b7b0 srv2!Smb2ExecuteRead+0x9a6

05 fffff880`05db1c80 fffff880`0404b6fb srv2!SrvProcessPacket+0xa0

06 fffff880`05db1cc0 fffff800`01960e5a srv2!SrvProcWorkerThread+0x2fb

07 fffff880`05db1d40 fffff800`016bad26nt!PspSystemThreadStartup+0x5a

08 fffff880`05db1d80 00000000`00000000nt!KiStartSystemThread+0x16

Next I dumped the driver dispatch routine noted in the KeBugCheckoutput above using the ln command. This points to fltmgr!FltpDispatch which tells me we have a filter manager minifilter driver making calls to disable APCs but rudely forgetting to re-enable them. As I noted above we save the state info before the call to IoCallDriver().

0: kd> ln fffff88001345610

(fffff880`01345610) fltmgr!FltpDispatch | (fffff880`01345710) fltmgr!FltReleasePushLock

Exact matches:

fltmgr!FltpDispatch (<no parameter info>)

Now the goal was to determine which minifilter is leaving the “Do Not Disturb” sign on the door and forgetting to remove it. We can find this using the fltmgr device object. The “saved state” structure is passed to VfAfterCallDriver as the first parameter so I switched to the VfAfterCallDriverframe (second frame) to dig it out. I used the /r flag to show the original values of the registers for this frame.

0: kd> .frame /r 2

02 fffff880`05db1b50 fffff800`01b6cc2e nt!VfAfterCallDriver+0x33e

rax=0000000000000000 rbx=fffffa804b729790 rcx=00000000000000c4

rdx=00000000000000c5 rsi=fffffa804a3b0000 rdi=fffff8000183ce80

rip=fffff80001b66b4e rsp=fffff88005db1b50 rbp=fffffa804de8c290

r8=fffff88001345610 r9=000000000000ffff r10=fffff80001b7a640

r11=0000000000000000 r12=000000004de8c290 r13=0000000000000000

r14=0000000000000000 r15=0000000000000000

iopl=0 nv up ei ng nz na pe nc

cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b efl=00000282

nt!VfAfterCallDriver+0x33e:

fffff800`01b66b4e cc int 3

Parameter 1 on x64 is always passed via rcx. I dumped the assembly for VfAfterCallDriver and confirmed the value in rcx (the base of the saved state structure) is moved to rbx.

0: kd> u nt!VfAfterCallDriver

nt!VfAfterCallDriver:

fffff800`01b66810 48895c2410 mov qword ptr[rsp+10h],rbx

fffff800`01b66815 48896c2418 mov qword ptr[rsp+18h],rbp

fffff800`01b6681a 4889742420 mov qword ptr[rsp+20h],rsi

fffff800`01b6681f 57 push rdi

fffff800`01b66820 4154 push r12

fffff800`01b66822 4155 push r13

fffff800`01b66824 4883ec30 sub rsp,30h

fffff800`01b66828 488bfa mov rdi,rdx

fffff800`01b6682b 488bd9 mov rbx,rcx

The device object is stored in the save state information at offset 0xa0.

0: kd> ? fffffa804b729790 + 0xa0

Evaluate expression: -6046048151504 = fffffa80`4b729830

0: kd> dq fffffa80`4b729830 l1

fffffa80`4b729830 fffffa80`4a3b0060

0: kd> !devobj fffffa80`4a3b0060

Device object (fffffa804a3b0060) is for:

\FileSystem\FltMgr DriverObject fffffa80491fb7c0

Current Irp 00000000 RefCount 0 Type 00000008 Flags 00040000

DevExt fffffa804a3b01b0 DevObjExt fffffa804a3b0208

ExtensionFlags (0x80000800) DOE_DEFAULT_SD_PRESENT, DOE_DESIGNATED_FDO

Characteristics (0000000000)

AttachedTo (Lower) fffffa804a3b1030 \FileSystem\Ntfs

Device queue is not busy.

0: kd> !devstack fffffa80`4a3b0060

!DevObj !DrvObj !DevExt ObjectName

> fffffa804a3b0060 \FileSystem\FltMgr fffffa804a3b01b0

fffffa804a3b1030 \FileSystem\Ntfs fffffa804a3b1180

As http://msdn.microsoft.com/en-us/library/ff541610(v=vs.85).aspxexplains – “The filter manager is installed with Windows, but it becomes active only when a minifilter driver is loaded. The filter manager attaches to the file system stack for a target volume. A minifilter driver attaches to the file system stack indirectly, by registering with the filter manager for the I/O operations the minifilter driver chooses to filter.”

Using the power of the fltkd extension, I dumped the volume information associated with this device object. From the output below, we can extract the name of the filter attached to the volume. The culprit is named BadDriver.sys. The customer removed the driver and the problem went away long enough for the vendor to create an update for BadDriver.sys. Happy Ending!

0: kd> !fltkd.volume fffffa80`4a3b0060

FLT_VOLUME: fffffa804a3b0800 "\Device\HarddiskVolume3"

FLT_OBJECT: fffffa804a3b0800 [04000000] Volume

RundownRef : 0x000000000000020a (261)

PointerCount : 0x00000001

PrimaryLink : [fffffa804ae06810-fffffa804a2b16f0]

Frame : fffffa8049fcd420 "Frame 0"

Flags : [00000064] SetupNotifyCalledEnableNameCaching FilterAttached

FileSystemType : [00000002] FLT_FSTYPE_NTFS

VolumeLink : [fffffa804ae06810-fffffa804a2b16f0]

DeviceObject : fffffa804a3b0060

DiskDeviceObject : fffffa804a1c0350

FrameZeroVolume : fffffa804a3b0800

VolumeInNextFrame : 0000000000000000

Guid : "\??\Volume{552791b0-455d-11de-b7b9-00145eed6acc}"

CDODeviceName : "\Ntfs"

CDODriverName : "\FileSystem\Ntfs"

TargetedOpenCount : 258

Callbacks : (fffffa804a3b0910)

ContextLock : (fffffa804a3b0cf8)

VolumeContexts : (fffffa804a3b0d00) Count=0

StreamListCtrls : (fffffa804a3b0d08) rCount=2871

FileListCtrls : (fffffa804a3b0d88) rCount=0

NameCacheCtrl : (fffffa804a3b0e08)

InstanceList : (fffffa804a3b0890)

FLT_INSTANCE: fffffa804b5b1010 "BadDriver.sys Instance" "189600"

Debugging a Debugger to Debug a Dump

ntdebug — Wed, 27 Feb 2013 17:30:51 GMT

Recently I came across an instance where my debugger did not do what I wanted. Rarely do computers disobey me, but this one was unusually stubborn. There was no other option; I had to bend the debugger to my will.

There are many ways to make a computer program do what you want. If you have the source code you can rewrite and recompile the program. If you have a hex editor you can edit the code of the binary. A shim can be used to modify a program at runtime. In this instance I was in a hurry and I was ok with a temporary solution, so I used a debugger to change the execution of the debugger while it ran.

Debug a debugger? Can you do such a thing? Of course you can.

In this example a memory dump was captured of a system and I was asked to determine if the system had run out of desktop heap. Usually the !dskheap command can be used to determine how much heap has been used by each desktop. Unfortunately, this command failed me.

23: kd> !dskheap

Error Reading TotalFreeSize from nt!_HEAP @ fffffa8019c65c00

Failed to GetHeapInfo for desktop @fffffa8019c65c00

EnumDsktps failed on Winsta: 19c4f090FillWinstaArray failed

The error indicates that the command couldn’t read from the _HEAP structure at fffffa8019c65c00 for desktop fffffa8019c65c00. Further investigation found that reason I got this error is that the heap for the desktop in question is not valid memory. Because the memory is described by a prototype PTE I assume that the heap has not been initialized (Note: See Windows Internals’ Memory Management chapter for more information about proto PTEs).

23: kd> dt win32k!tagDESKTOP fffffa8019c65c00

+0x000 dwSessionId : 0

+0x008 pDeskInfo : 0xfffff900`c05e0a70 tagDESKTOPINFO

+0x010 pDispInfo : 0xfffff900`c0581e50 tagDISPLAYINFO

+0x018 rpdeskNext : 0xfffffa80`19c6ef20 tagDESKTOP

+0x020 rpwinstaParent : 0xfffffa80`19c4f090 tagWINDOWSTATION

+0x028 dwDTFlags : 0x110

+0x030 dwDesktopId : 0x19c65c00`00000003

+0x038 spmenuSys : (null)

+0x040 spmenuDialogSys : (null)

+0x048 spmenuHScroll : (null)

+0x050 spmenuVScroll : (null)

+0x058 spwndForeground : (null)

+0x060 spwndTray : (null)

+0x068 spwndMessage : 0xfffff900`c05e0d90 tagWND

+0x070 spwndTooltip : 0xfffff900`c05e0fa0 tagWND

+0x078 hsectionDesktop : 0xfffff8a0`00ef08e0 Void

+0x080 pheapDesktop : 0xfffff900`c05e0000 tagWIN32HEAP

+0x088 ulHeapSize : 0x18000

+0x090 cciConsole : _CONSOLE_CARET_INFO

+0x0a8 PtiList : _LIST_ENTRY [ 0xfffffa80`19c65ca8 - 0xfffffa80`19c65ca8 ]

+0x0b8 spwndTrack : (null)

+0x0c0 htEx : 0n0

+0x0c4 rcMouseHover : tagRECT

+0x0d4 dwMouseHoverTime : 0

+0x0d8 pMagInputTransform : (null)

23: kd> dd 0xfffff900`c05e0000

fffff900`c05e0000 ???????? ???????? ???????? ????????

fffff900`c05e0010 ???????? ???????? ???????? ????????

fffff900`c05e0020 ???????? ???????? ???????? ????????

fffff900`c05e0030 ???????? ???????? ???????? ????????

fffff900`c05e0040 ???????? ???????? ???????? ????????

fffff900`c05e0050 ???????? ???????? ???????? ????????

fffff900`c05e0060 ???????? ???????? ???????? ????????

fffff900`c05e0070 ???????? ???????? ???????? ????????

23: kd> !pte fffff900`c05e0000

VA fffff900c05e0000

PXE at FFFFF6FB7DBEDF90 PPE at FFFFF6FB7DBF2018 PDE at FFFFF6FB7E403010 PTE at FFFFF6FC80602F00

contains 000000076245C863 contains 0000000762569863 contains 000000045FA17863 contains F8A000F4F9780400

pfn 76245c ---DA--KWEV pfn 762569 ---DA--KWEV pfn45fa17 ---DA--KWEV not valid

Proto: FFFFF8A000F4F978

There are many desktops in this session and I wanted to know about the usage of the other desktops, but the !dskheap command stopped after just one error. I needed to force it to continue after this error, so I launched a debugger to debug my debugger. There is a command to do this, just run .dbgdbg.

23: kd> .dbgdbg

Debugger spawned, connect with

"-remotenpipe:icfenable,pipe=cdb_pipe,server=NINJA007"

For clarity I will call the original debugger where I ran !dskheap debugger1, and the new debugger spawned by .dbgdbg debugger2 .

Before switching to debugger2 I need to know what I am going to debug. The error message gives a hint about where to set a breakpoint, I am looking for a failure from GetHeapInfo.

23: kd> !dskheap

Error Reading TotalFreeSize from nt!_HEAP @ fffffa8019c65c00

Failed to GetHeapInfo for desktop @fffffa8019c65c00

EnumDsktps failed on Winsta: 19c4f090FillWinstaArray failed

I need to know which module GetHeapInfo is in, the .extmatch match command indicates which module contains the !dskheap command.

23: kd> .extmatch dskheap

!kdexts.dskheap

Switching to debugger2 I set a breakpoint on kdexts!GetHeapInfo. Use Ctrl+C to trigger a debug break in cdb (this is the same as a Ctrl+Break in windbg).

0:004> bp kdexts!GetHeapInfo

0:004> g

Switch back to debugger1 and run the !dskheap command.

23: kd> !dskheap

In debugger2 I have hit the breakpoint.

Breakpoint 0 hit

kdexts!GetHeapInfo:

000007f9`4237b9b0 4055 push rbp

The error says GetHeapInfo failed, so I am interested in what this function returns. To see what GetHeapInfo returns I go up one level in the stack and set a new breakpoint on the code just after it returns. This new breakpoint will also dump the return value of GetHeapInfo (return values are always in the rax register).

0:000> gu

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> r rax

rax=0000000000000000

0:000> bc *

0:000> bp 000007f9`4237b483 "r rax"

0:000> g

The next time the breakpoint hit the return value was 1, which in this instance means GetHeapInfo failed. This is where I exerted my control over the computer: I forced the return value to 0.

rax=0000000000000001

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> r rax=0

I ran through the other breakpoints and changed rax as necessary.

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000001

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> r rax=0

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

Everything was going well, until the computer defied me again. The !dskheap output computes the percentage of heap usage by dividing the bytes used by the size of the heap. Unfortunately, the size of the heap was left at 0 for the two heaps where I changed the return value. It is well known that only Chuck Norris can divide by zero; to prevent a roundhouse kick to your computer the processor generates an exception.

(2d0.928): Integer divide-by-zero - code c0000094 (first chance)

First chance exceptions are reported before any exception handling.

This exception may be expected and handled.

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> r r11

r11=0000000000000000

0:000> r rax

rax=0000000000000000

0:000> g

Fortunately debugger1 handles the divide by zero exception and it is easy to run !dskheap again.

23: kd> !dskheap

Back in debugger2 I set a new breakpoint on the div instruction that outputs the divisor. When the divisor (r11) is 0 I changed it to a non-zero value to avoid the wrath of Mr. Norris.

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> bp 000007f9`4237b90e

0:000> bp 000007f9`4237b90e "r r11"

breakpoint 1 redefined

0:000> g

rax=0000000000000001

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> r rax=0

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

rax=0000000000000001

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> r rax=0

0:000> g

rax=0000000000000000

kdexts!EnumDsktps+0x197:

000007f9`4237b483 4885c0 test rax,rax

0:000> g

r11=0000000000033333

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> g

r11=0000000000000000

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> r r11=1

0:000> g

r11=00000000000007ae

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> g

r11=0000000000013333

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> g

r11=0000000000013333

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> g

r11=0000000000013333

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> g

r11=0000000000000000

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> r r11=1

0:000> g

r11=0000000000013333

kdexts!DisplayInfo+0x2ee:

000007f9`4237b90e 49f7f3 div rax,r11

0:000> g

Finally, back in debugger1 I now have complete output for !dskheap. After a few strategic modifications of the program’s execution I got it to output the data I wanted. As it turns out we aren’t out of desktop heap after all.

23: kd> !dskheap

Error Reading TotalFreeSize from nt!_HEAP @ fffffa8019c65c00

Error Reading TotalFreeSize from nt!_HEAP @ fffffa801a53ea30

Winstation\Desktop Heap Size(KB) Used Rate(%)

------------------------------------------------------------

WinSta0\Default 20480 0%

WinSta0\Disconnect 0 0%

WinSta0\Winlogon 192 2%

Service-0x0-3e7$\Default 7680 1%

Service-0x0-3e4$\Default 7680 0%

Service-0x0-3e5$\Default 7680 0%

Service-0x0-26f46a$\Default 0 0%

Service-0x0-2706f2$\Default 7680 0%

------------------------------------------------------

Total Desktop: ( 51392 KB - 8 desktops)

Session ID: 0

============================================================

How to Setup a Debug Crash Cart to Prevent Your Server from Flat Lining

ntdebug — Thu, 31 Jan 2013 23:10:41 GMT

This is Ron Stock from the Global Escalation Services team and I recently had the task of live debugging a customer’s remote server. In debug circles we use what is known as a crash cart to live debug production servers. The phrase conjures up visions of a wheeled cabinet containing an emergency defibrillator, a heart monitor and latex gloves. Luckily for our purposes, the term merely denotes a machine setup with the Debugging Tools for Windows. This life saving machine is attached to the ailing production server for debugging and no medical degree is required.

The ailing production server is referred to as the Target Computer and the Debugging Tools for Windows are installed on the Host computer. The machines are attached with either a null-modem cable, 1394 cable, a special USB cable, or an ethernet cable (network debugging was added in Windows 8). Below I outline serial debugging because this is the most common technique. In future articles I plan to discuss configuring the other methods.

Serial Connection Setup

A null-modem cable is a serial cable used to send data between two serial ports and it can be cheaply purchased at most electronics stores. Be aware these are different from standard serial cables because the transmit and receive lines are cross linked.

Plug the null-modem cable into a serial port on each of the computers. The serial port on the target computer must be built into the system, add on components such as PCI cards will not work for serial debugging on the target computer.

Target Computer setup

1. To enable debugging enter the following command from an elevated command prompt.

bcdedit /debug on

2. In most systems the default debug settings are sufficient. The current settings can be verified with the below command.

bcdedit /dbgsettings

3. Use the below command if you need to change the debug settings, where x is the number of the COM port connected to the null modem cable on the target machine and rate is the baud rate desired for debugging. The rate is usually 115200.

bcdedit /dbgsettings serial debugport:x baudrate:115200

5. Reboot the target computer.

Host Computer setup

1. First install the Windows Debugging Tools on the host computer. Navigate to the Windows Software Development Kit (SDK) currently located at this link http://msdn.microsoft.com/en-US/windows/hardware/hh852363 and choose the download option.

a. If you are not able to install the SDK on the host computer, the debugging tools for windows can be installed to a different system and the debugger directory can be copied to the host computer.

2. Click Next until you see the Select the features you want to install screen.

3. Select only the option named Debugging Tools for Windows and click the Install button. I typically install the tools to a directory named C:\debugger

4. After the Windows Debugging Tools are installed I set my symbol path by setting the environment variable _NT_SYMBOL_PATH. I recommend setting it to the public symbol server SRV*c:\localsymbols*http://msdl.microsoft.com/download/symbols. If you prefer, you can specify any path in place of ‘c:\localsymbols’.

5. Open the debugger by running windbg.exe from the c:\debugger folder.

6. On the File menu, choose Kernel Debug.

7. In the Kernel Debugging dialog box, open the COM tab.

8. In the Baud rate box, enter the same rate you selected for the Target Machine in the steps above. This is usually 115200.

9. In the Port box, enter COMx where x is the COM port connected to the null modem cable on this computer. In my example I plugged my null modem cable to com port 1 so I typed com1 in the field.

a. It is not necessary to use the same port number on both the target and the host. For example, it is possible to use com1 on the target and com2 on the host.

10. Click OK and you’ll receive a message indicating the Host computer is waiting to connect.

11. From the Debug menu select Break will cause the debugger to break into the target machine and give you the opportunity to debug your ailing production server. Good Luck!!