WPP and KD

  • Article

Industrial-strength tracing in an industrial-strength debugger

Last time we talked about controlling WPP from the command-line.  This is great if you need to send instructions to a customer to collect logs, or if you want to automatically enable NDIS tracing on all your test machines.   Because you don't need a debugger attached, the command-line approach is also the easiest.

As an alternative to the command-line, there is also a debugger extension that lets you control trace sessions entirely from within kd.  And you don't need to be a kd-junkie to appreciate the value of this feature -- if a machine has already bugchecked, then this is the most reliable way to scrape NDIS's traces out of memory.  (Even if you are logging to a file, the file might not have flushed to disk yet).

The key is the !wmitrace extension.  Its documentation describes lots of cool tricks, including how to save traces to a file on disk, get messages printed to the debugger in real-time (like DbgPrint!), and change to a bigger buffer to avoid missing high-throughput traces.  I'll let you read the docs on your own; the simplest usage looks like this:

0: kd> !wmitrace.start ndis
Break instruction exception - code 80000003 (first chance)
Remote operation finished with NTSTATUS 0x00000000
1: kd> !wmitrace.enable ndis {DD7A21E6-A651-46D4-B7C2-66543067B869} -level 4 -flag 0x31f3
Break instruction exception - code 80000003 (first chance)
Remote operation finished with NTSTATUS 0x00000000
0: kd> g

Now tracing is enabled.  You can repro the bug or just leave the traces running continually in the background.  (By default, they go to a circular buffer, so you'll always have access to the most recent few traces).

Later, when you want to dump the contents of the log, you'll need NDIS's TMF files.  In this example, I have already uncompressed NDISTMF.ZIP into a directory on the local machine (the one running windbg) into C:\NDIS_TMF:

0: kd> !wmitrace.searchpath c:\ndis_tmf
Trace Format search path is: 'c:\ndis_tmf'
0: kd> !wmitrace.logdump ndis
(WmiTrace)LogDump for Logger Id 0x1d
Processing Global List:   4 Buffers
Total of 4 buffers found, now sorting entries
LOGGED MESSAGES (20):
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]==>NdisWriteErrorLogEntry: Miniport FFFFFA80064851A0, ErrorCode a004001b
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]<==NdisWriteErrorLogEntry: Miniport FFFFFA80064851A0, ErrorCode a004001b
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]==>ndisSwapFilterHandlers: Filter FFFFFA80069098E0, FakeStatus c023001f, Flags 2
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]<==ndisSwapFilterHandlers: Filter FFFFFA80069098E0
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]==>ndisSwapFilterHandlers: Filter FFFFFA8006906C90, FakeStatus c023001f, Flags 1
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]<==ndisSwapFilterHandlers: Filter FFFFFA8006906C90
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]==>ndisSwapFilterHandlers: Miniport FFFFFA80064851A0, FakeStatus c023001f, Flags 1
[0]03C0.01EC::03/24/2011-00:41:32.009 [mp]<==ndisSwapMiniportHandlers: Miniport FFFFFA80064851A0
[0]0004.003C::03/24/2011-00:41:32.035 [mp]==>ndisSwapFilterHandlers: Miniport FFFFFA80064031A0, FakeStatus c023001f, Flags 2
[0]0004.003C::03/24/2011-00:41:32.035 [mp]<==ndisSwapMiniportHandlers: Miniport FFFFFA80064031A0
[0]0000.0000::03/24/2011-00:41:36.441 [mp]==>NdisWriteErrorLogEntry: Miniport FFFFFA80064851A0, ErrorCode 60040020
[0]0000.0000::03/24/2011-00:41:36.441 [mp]<==NdisWriteErrorLogEntry: Miniport FFFFFA80064851A0, ErrorCode 60040020
[0]0000.0000::03/24/2011-00:41:36.441 [mp]==>ndisRestoreFilterHandlers: Filter FFFFFA80069098E0, Current fake status c023001f, Flags 2
[0]0000.0000::03/24/2011-00:41:36.441 [mp]<==ndisRestoreFilterHandlers: Filter FFFFFA80069098E0
[0]0000.0000::03/24/2011-00:41:36.441 [mp]==>ndisRestoreFilterHandlers: Filter FFFFFA8006906C90, Current fake status c023001f, Flags 1
[0]0000.0000::03/24/2011-00:41:36.441 [mp]<==ndisRestoreFilterHandlers: Filter FFFFFA8006906C90
[0]0000.0000::03/24/2011-00:41:36.441 [mp]==>ndisRestoreFilterHandlers: Miniport FFFFFA80064851A0, Current fake status c023001f, Flags 1
[0]0000.0000::03/24/2011-00:41:36.441 [mp]<==ndisRestoreMiniportHandlers: Miniport FFFFFA80064851A0
[1]025C.0CB8::03/24/2011-00:41:39.012 [mp]==>ndisHandleLegacyTransport: pDevice FFFFF8800A28F900
[1]025C.0CB8::03/24/2011-00:41:39.012 [mp]<==ndisHandleLegacyTransport
Total of 20 Messages from 4 Buffers

As you see, the last 20 messages are displayed, although you can go back a little further than that with the -t parameter to !wmitrace.logdump.

Finally, you can disable tracing with this:

0: kd> !wmitrace.stop ndis
Break instruction exception - code 80000003 (first chance)
Remote operation finished with NTSTATUS 0x00000000