How to generate and view a WinUSB debug trace log

This post has been republished via RSS; it originally appeared at: Microsoft USB Blog articles.

First published on MSDN on Feb 05, 2010

Updated 7/12/2011 with Windows 7 SP1 format data (in addition to RTM format data)


Hello, my name is Don Miller.  I am a software developer on the Windows USB team.  In this blog post, I'm going to describe how to get debug trace messages from WINUSB.SYS driver. WinUSB is a generic USB driver provided by Microsoft to enable usermode applications to access simple USB devices through a software library . It uses WPP software tracing to log debug messages.  Enabling and viewing the WinUSB debug log can be helpful to Windows device driver developers who are using WinUSB.SYS as the functional driver for their USB device(s).  WinUSB.SYS will emit various debug messages to its debug log and can be useful for checking for errors and other useful information.  Below are instructions on how to know if a USB device is using WINUSB.SYS, how to enable/disable WinUSB debug logging and instructions on how to view the log:


How to know if a USB device is using WINUSB.SYS
===============================================
1) Open Device Manager
2) Choose the View Menu option and click on Devices By Connection
3) Find your USB device amongst the USB host controllers installed on the system
4) Right click on the USB device in question and choose Properties
5) In the Properties menu, choose the Drivers tab and click on Driver Details
6) If WINUSB.SYS is in the list of Driver Files then the USB device is using WINUSB.SYS


How to start/stop/view WinUSB logging:
======================================
1) Copy attached win7_winusbtrace_tool.zip to a local folder
2) Copy tracefmt.exe and tracelog.exe into same local directory or include on your path since winusbtrace.cmd is dependent on these two tools.  Tracefmt.exe and tracelog.exe are available in the Win7 WDK ( http://www.microsoft.com/downloads/details.aspx?FamilyID=2105564e-1a9a-4bf4-8d74-ec5b52da3d00&displaylang=en ).  Once Win7 WDK is installed, these two files will be in C:\WinDDK\7600.16385.0\tools\tracing\ directory.
3) Open a command window with local administrator credentials and unzip the attached win7_winusbtrace_tool.zip
4) At command prompt, type below command to set the _TMF_FILES environment variable that winusbtrace.cmd is dependent on:

set _TMF_FILES=<path to win7_winusb.tmf included in ZIP file>


5) Run winusbtrace.cmd with below options:


winusbtrace start
winusbtrace stop
winusbtrace view
winusbtrace view_realtime


Note that if there are multiple USB devices using WinUSB.SYS then the debug log will have all those USB devices debug output in the one WinUSB debug log.  Below is a sample WinUSB debug log that uses one OSRUSBFX/2 device:


Below format is: [ CPUNumber ] ProcessID . ThreadID :: SystemTime - WinUSB specific debug string
.
.
.
[2]0004.003C::02/04/2010-11:43:50.175 - Preparing hardware
[2]0004.003C::02/04/2010-11:43:50.175 - Resetting Default settings
[2]0004.003C::02/04/2010-11:43:50.175 - Enter: WinUSB_InitControlPipe
[2]0004.003C::02/04/2010-11:43:50.175 - Exit: WinUSB_InitControlPipe (STATUS_SUCCESS)
[3]0004.003C::02/04/2010-11:43:50.176 - Enter: WinUSB_D0Entry
[3]0004.003C::02/04/2010-11:43:50.176 - Starting Read Io Target
[3]0004.003C::02/04/2010-11:43:50.176 - Starting Read Io Target
[3]0004.003C::02/04/2010-11:43:50.176 - Exit: WinUSB_D0Entry (STATUS_SUCCESS)
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_VERSION_EXCHANGE
[1]05A4.08BC::02/04/2010-11:43:50.176 - Enter: WinUSB_ExchangeVersion
[1]05A4.08BC::02/04/2010-11:43:50.176 - Exit: WinUSB_ExchangeVersion (STATUS_SUCCESS)
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_GET_DESCRIPTOR
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_GET_DESCRIPTOR
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_GET_DESCRIPTOR
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_RESET_DEFAULTS
[1]05A4.08BC::02/04/2010-11:43:50.176 - Enter: WinUSB_InitControlPipe
[1]05A4.08BC::02/04/2010-11:43:50.176 - Exit: WinUSB_InitControlPipe (STATUS_SUCCESS)
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_GET_DESCRIPTOR
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_QUERY_DEVICE_INFORMATION
[1]05A4.08BC::02/04/2010-11:43:50.176 - IOCTL_WINUSB_SET_PIPE_POLICY
[1]05A4.08BC::02/04/2010-11:45:31.226 - Unsupported Pipe Policy specified (8) <------Indicates that an incorrect pipe policy was passed into WINUSB.SYS
[1]05A4.08BC::02/04/2010-11:45:32.252 - IOCTL_WINUSB_SET_PIPE_POLICY
[1]05A4.08BC::02/04/2010-11:45:34.271 - IOCTL_WINUSB_SET_PIPE_POLICY
[1]05A4.08BC::02/04/2010-11:45:35.446 - IOCTL_WINUSB_SET_PIPE_POLICY
[1]05A4.08BC::02/04/2010-11:45:36.126 - IOCTL_WINUSB_CONTROL_TRANSFER
[1]05A4.08BC::02/04/2010-11:45:36.126 - PIPE0: (0000000c) Submitting Control Request to endpoint 0
[0]0000.0000::02/04/2010-11:45:36.126 - PIPE0: (0000000c) Control request complete with status (STATUS_SUCCESS)
[1]05A4.08BC::02/04/2010-11:45:36.127 - IOCTL_WINUSB_CONTROL_TRANSFER
[1]05A4.08BC::02/04/2010-11:45:36.127 - PIPE0: (0000000d) Submitting Control Request to endpoint 0
[0]0000.0000::02/04/2010-11:45:36.127 - PIPE0: (0000000d) Control request complete with status (STATUS_SUCCESS)
[3]05A4.08BC::02/04/2010-11:45:36.128 - IOCTL_WINUSB_READ_PIPE
[3]05A4.08BC::02/04/2010-11:45:36.128 - PIPE129: (0000000e) The read has been added to the read queue
[3]05A4.08BC::02/04/2010-11:45:36.128 - PIPE129: (0000000e) The read for 1 bytes is being handled
[3]05A4.08BC::02/04/2010-11:45:36.128 - PIPE129: (0000000e) Reading 73 bytes from the device
[3]05A4.08BC::02/04/2010-11:45:36.128 - IOCTL_WINUSB_READ_PIPE
[3]05A4.08BC::02/04/2010-11:45:36.128 - PIPE129: (0000000f) The read has been added to the read queue
[2]0000.0000::02/04/2010-11:45:36.128 - PIPE129: (0000000e) Read request for 1 bytes has completed with 1 bytes
[2]0000.0000::02/04/2010-11:45:36.128 - PIPE129: (0000000f) The read for 1 bytes is being handled
[2]0000.0000::02/04/2010-11:45:36.128 - PIPE129: (0000000f) Reading 73 bytes from the device
[3]05A4.055C::02/04/2010-11:45:36.128 - IOCTL_WINUSB_READ_PIPE
[3]05A4.055C::02/04/2010-11:45:36.128 - PIPE129: (00000010) The read has been added to the read queue
.
.
.


The above WinUSB debug log shows a debug message that indicates an error related to a WinUSB client that has passed in an incorrect pipe policy. When issues occur with a USB device that is using WinUSB then by looking at the WinUSB debug log it could save you trouble-shooting time.

Thanks,

Don Miller
Microsoft USB Development
=========================


win7_winusbtrace_tool.zip

Leave a Reply

Your email address will not be published. Required fields are marked *

*

This site uses Akismet to reduce spam. Learn how your comment data is processed.