From: "Adam Kropelin" <akropel1@rochester.rr.com>
To: "Kern Sibbald" <kern@sibbald.com>
Cc: "Apcupsd-users" <apcupsd-users@lists.sourceforge.net>
Subject: Reading a usbsnoop trace
Date: Mon, 23 Aug 2004 21:51:50 -0400
Some users have had good luck using the 'usbsnoop' tool
(http://benoit.papillault.free.fr/usbsnoop/index.php) to capture USB traces
of PowerChute on Windows. The output from usbsnoop is a text file containing
a transcript of all the USB communication with a particular device. The
format is a bit wonky, but it generally contains enough information to see
how PowerChute sets various UPS parameters and how the UPS responds.
The traces consist of a series of request/response pairs (called "URBs" in
USB lingo). First a request from the host to the device and then a response
from the device to the host. The request URB is always sent first and is
followed by the response. Note that more than one request may be outstanding
at a time so the response is not always the very next URB in the trace,
although it usually is. The URB number can be used to match responses with
requests.
Here is an example URB, number 108:
[4945 ms] UsbSnoop - DispatchAny(f7c08610) : IRP_MJ_INTERNAL_DEVICE_CONTROL
[4945 ms] UsbSnoop - MyDispatchInternalIOCTL(f7c09e80) : fdo=8602b460,
Irp=85e84cb0, IRQL=0
[4945 ms] >>> URB 108 going down >>>
-- URB_FUNCTION_CLASS_INTERFACE:
TransferFlags = 00000001 (USBD_TRANSFER_DIRECTION_IN,
~USBD_SHORT_TRANSFER_OK)
TransferBufferLength = 00000005
TransferBuffer = f7f1efd0
TransferBufferMDL = 00000000
UrbLink = 00000000
RequestTypeReservedBits = 00000022
Request = 00000001
Value = 00000323
Index = 00000000
[4950 ms] UsbSnoop - MyInternalIOCTLCompletion(f7c09db0) : fido=863b9030,
Irp=85e84cb0, Context=86001650, IRQL=2
[4950 ms] <<< URB 108 coming back <<<
-- URB_FUNCTION_CONTROL_TRANSFER:
PipeHandle = 86109ac8
TransferFlags = 0000000b (USBD_TRANSFER_DIRECTION_IN,
USBD_SHORT_TRANSFER_OK)
TransferBufferLength = 00000003
TransferBuffer = f7f1efd0
TransferBufferMDL = 860ba270
00000000: 23 7f 00
UrbLink = 00000000
SetupPacket =
00000000: a1 01 23 03 00 00 05 00
usbsnoop uses the term "going down" to refer to the host->device request and
"coming back" to refer to the device->host response. The request and
response are both timestamped with an offset in msec since usbsnoop started
up.
Several lines can be safely ignored. Lines starting with a timestamp and
"UsbSnoop - ..." generally contain Windows-specific usbsnoop debugging info
and are of no use to us. Also, PipeHandle, TransferBuffer,
TransferBufferMDL, UrbLink, and SetupPacket fields are not particularly
useful, either.
Also, keep in mind that usbsnoop will not display fields that it considers
"uninteresting" and it will display additional fields sometimes if it thinks
they are interesting. For example, some packets will not show the
RequestTypeReservedBits field if the bits are set to indicate a standard USB
transaction. This fluctuation of displayed fields can be really aggravating
since it makes comparison and trend-spotting harder.
The URBs can be of different transfer types and often the request and
response are not the same type. I'm going to vastly over-simplify and talk
about what we care about for apcupsd. Generally speaking, all the
interesting data for apcupsd is in one of two pairs. Either
URB_FUNCTION_CLASS_INTERFACE (request) -> URB_FUNCTION_CONTROL_TRANSFER
(response) or URB_FUNCTION_BULK_OR_INTERRUPT_TRANSFER (both request &
response) URBs. The CONTROL_TRANSFERs are when a specific data item is read
from or written to the UPS by the host. The INTERRUPT_TRANSFERs are when the
UPS spontaneously sends the host some information. Note that even
INTERRUPT_TRANSFERs have both a request and a response; the request is
basically empty and the response comes back filled in.
CONTROL_TRANSFER:
The CONTROL_TRANSFER URBs begin with a CLASS_INTERFACE request in which the
host identifies what report it wants to access from the ups. The reports
consist of a one byte tag which identifies the report in question and a
multi-byte (generally 1, 2, or 3 byte) data section. For us, the
CLASS_INTERFACE transfers of interest have RequestTypeReservedBits=00000022
(this indicates a class-specific command and all UPS commands are specific
to the HID class) and have a Request=00000001 (read) or Request=0000000a
(write). The example above shows a read request. The actual report tag
number is the last byte in the Value line (0x23 in the example above). Down
in the response packet the line after "TransferBufferMDL" contains the data
sent back by the UPS: "23 7f 00". The 0x23 is the report tag again and
0x007f is the value (little endian). From hid-ups we can look up report 0x23
(decimal 35):
FeatureReport 35
Field 0, app UPS, phys Output
Usage 0, HighVoltageTransfer = XYZ Volts
So we can see that in the example packet the UPS is reporting a
HighVoltageTransfer of 127 V (0x007f). Note that the report tags differ
between UPS models so you need to look at hid-ups output for the same basic
model as you're tracing.
A write looks about the same except the request packet says
"Request=0000000a" and the data line containing the report tag and value is
in the request packet instead of the response packet.
INTERRUPT_TRANSFER:
Interrupt transfers in our case are all reads. You can basically ignore the
request part of the URB because it contains no useful data. The response
will have a data line just like a CONTROL_TRANSFER response and you can
decode the report tag and value from that.
THE EASY WAY:
Ok, so now that I've dragged you through the hard way I'll tell you how to
cheat. I wrote a tool that parses the trace and produces output showing one
URB per line and clearly stating the report tag, value, and whether it's a
read or a write. It also suppresses all reads that don't show a change in
state, so the trace isn't cluttered with repetitive reads of the same value.
The output looks like this:
[0001 s] 00058 READ 0x23 007f (127)
[0001 s] 00060 READ 0x24 006a (106)
[0001 s] 00052 * READ 0x1c 00 (0)
[0002 s] 00061 READ 0x40 0000 (0)
[0002 s] 00063 READ 0x41 0000 (0)
The columns are: timestamp (in seconds), URB number (so you can correlate it
to the full trace), READ/WRITE, report tag, and value in hex and (decimal).
A * between the URB number and transaction type indicates an interrupt
transfer as opposed to polling.
I've attached the code for the parsing tool "snoopdecode". It reads from
stdin and writes to stdout so you can do things like "cat mytrace.log |
snoopdecode | grep 0x23" and watch how a particular value changed over time.
Builds with plain old 'gcc -o snoopdecode snoopdecode.c'. It leaks memory.
It has no error checking. There are probably more than a few snoop traces
that will crash it terribly. But it's still easier than reading snoop output
by hand.
Hope this was useful; Feel free to ask questions...
--Adam
