Snooping the USB Data Stream

to log the control request information. After the read has completed, I add the following lines to log the actual data read from the device:

printk("control read: data ");
for (j = 0; j < ctrl.wLength; ++j)
    printk("%02x ", ctrl.data[j]);
printk("\n");

After doing much the same modification to the write section of the if statement, I build, reload the usbcore modules and verify that I now can log all control messages to and from the device. The messages returned are:

CONTROL
control read: bRequest=06 bRrequestType=80 wValue=0300 wIndex=0000
control read: data 00 00 61 63

Day 6: Looking at the modifications I have made to the kernel code, I think this work might be something other users might like to have. So, it is time to clean up the code to a state that the USB maintainer might accept for the main kernel source tree.

First, I recognized that the calls to printk() are incorrect. All printk() calls must be accompanied by a proper logging level. These logging levels are added to printk calls by pre-appending the proper KERN_ values to the message. The file include/linux/kernel.h contains the following valid values that must be used:

#define KERN_EMERG   "<0>" /* system is unusable               */
#define KERN_ALERT   "<1>" /* action must be taken immediately */
#define KERN_CRIT    "<2>" /* critical conditions              */
#define KERN_ERR     "<3>" /* error conditions                 */
#define KERN_WARNING "<4>" /* warning conditions               */
#define KERN_NOTICE  "<5>" /* normal but significant condition */
#define KERN_INFO    "<6>" /* informational                    */
#define KERN_DEBUG   "<7>" /* debug-level messages             */

So, I change the printk calls in the usbfs_ioctl() function from:

printk("CLAIMINTERFACE\n);

to:

printk(KERN_INFO "CLAIMINTERFACE\n);

Now the kernel janitors should not complain about improper printk() usage.

In looking further at the logging messages, however, it is hard to determine for what exact device the message is being logged. More information needs to be added to the printk() calls. Luckily, some macros already in the include/linux/device.h file can help us. They are the dev_printk() macro and its helper macros, dev_dbg(), dev_warn(), dev_info() and dev_err(). These macros all need an additional pointer to a struct device variable, which allows them to print out the unique device ID for the message. So I change the printk() calls again to look like this:

dev_info(&dev->dev, "CLAIMINTERFACE\n");

Then the control message printk() calls are changed to:

dev_info(&dev->dev, "control read: "
       "bRequest=%02x bRrequestType=%02x "
       "wValue=%04x wIndex=%04x\n",
       ctrl.bRequest, ctrl.bRequestType,
       ctrl.wValue, ctrl.wIndex);

dev_info(&dev->dev, "control read: data ");
for (j = 0; j < ctrl.wLength; ++j)
    printk("%02x ", ctrl.data[j]);
printk("\n");

The printk calls that dump the data do not need to be changed, as they still are printing on the same line as the call to dev_info().

Now the log messages are much more informative, looking like the following:

usb 1-1: CONTROL
usb 1-1: control read: bRequest=06 bRrequestType=80 wValue=0300 wIndex=0000
usb 1-1: control read: data 00 00 61 63

I can determine exactly what USB device is being talked to, which helps me weed out the messages for devices I do not care about.

Day 7: Oops, I now realize that if I expect this kernel change to be accepted by the community, I had better not always generate these messages. Otherwise, everyone would have their system logs overflowing with messages they do not care about. How to log messages only when asked?

I first look into making a new kernel build configuration option. A simple modification of the drivers/usb/core/Kconfig file adding a new option is simple, but in examining the required code changes, I soon realize that wrapping all of the new logging statements in a #ifdef CONFIG_USBFS_LOGGING statement would make the USB maintainer reject my kernel patch. #ifdef is not generally allowed within kernel code, as it cuts down on readability and makes maintaining the code over time almost impossible.

Instead, I look at making an option that can be changed at runtime. I add the following lines of code to the devio.c file:

static int usbfs_snoop = 0;
module_param (usbfs_snoop, bool, S_IRUGO | S_IWUSR);
MODULE_PARM_DESC (usbfs_snoop, "true to log all usbfs traffic");

This adds a new module parameter to the main usbcore module called usbfs_snoop. This can be seen after building the code by running the modinfo program:

$ modinfo usbcore
license: GPL
parm:    blinkenlights:true to cycle leds on hubs
parm:    usbfs_snoop:true to log all usbfs traffic

By loading the module with the following line:

modprobe usbcore usbfs_snoop=1