How to generate and view a WinUSB debug trace log


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


Comments (19)

  1. Lisbeth Salander says:

    Thanks. I’m new with WinDDK and debug traces, so this may be handy if/when I even am gonna work with WinUSB.

    Is there any plans on fixing support by several application/threads to the same device? Or will this have to be handled with using a system global mutex, or similar, among the relevant applications that will/may access the same USB device simultaneously?

    Keep blogging.

  2. Ury says:

    Hi Don,

    I’m considering using WinUSB as a way of quickly setting up an interface to my USB-connected embedded software.  While reading about WinUSB, it seemed to me like WinUSB, at least when using  *straightforwardly *, does not support multiple USB device connections.  This was later verified in my implementation (all USB devices other than the first one return an invalid handle).

    In your post you DO relate to multiple USB devices.  Am I missing anything here?

    Thanks,

     Ury

  3. George Barbehenn says:

    Don:

    Based on tracing with this trace provider, I believe there is a bug in WinUSB.  The bug is that if a WinUSB_readpipe is done and the device sends a legitimate 0 byte packet, WinUSB_readpipe terminates with a timeout (121) and reports 'fail'.

    Besides the fact that it is legitimate to send a 0 byte packet, it is the only way to terminate a transaction for which the number of bytes sent equals a multiple of the endpoint size, unless you know how many bytes will be sent a priori.

    Coding using counts is bad mojo, as if the sender and receiver disagree on the number of bytes, the channel will hang.  But, in my case I don't have enough resources on my device to buffer the entire message anyway, and so send it in 16 byte increments.  Thus neither the sender nor the reciever know the message size a priori, and I have to terminate with a short packet.  Or a 0 length packet if the actual message length is a multiple of the endpoint size.  The latter fails on WinUSB_readpipe with a semaphore timeout (121).

  4. Peter Petrov says:

    Hi Don:

    After following your instructions I'm getting:

    ———————————————-

    Could not start logger: WINUSB

    Operation Status:       5L

    Access is denied.

    Operation Status:       5L      Access is denied.

    Thanks a lot,

    Peter

  5. Baruch says:

    What does it take to make this work under XP (SP3)? all I get is a lot of "Unknown( 17): GUID=xxx (No Format Information found)." …

  6. Gyanendra says:

    Hello USB experts,

    Is there a tool/way to capture USBStack (USBHub and USBPort) trace like above in WinXP and Vista?

    BR,

    Gyanendra

  7. Pavan says:

    I would like to have this utility on XP (SP3) as well, what should we do to get this working ?

  8. Ben says:

    I get an access denied error when I try to run winusbtrace start

  9. USB Blog says:

    Ben, if you're not already doing this, try opening the command prompt by right-clicking its shortcut and selecting "Run as Administrator".

  10. Hi,

    I've been trying to get this to work in Windows 7 x64 (and Vista x64) using WinUSB v1.9, your attached files plus tracefmt.exe and tracelog.exe from WDK 7600.16385.1

    Firstly, there may be typos in the attached winusbtrace.cmd, there are two instances where the following occurs "%_TMF_FILES%"win7_winusb.tmf

    I assume that the second double quote is in the wrong place.

    After collecting bulk USB data from my device, the report I get from ‘winusbtrace view’ begins as follows:

    Unknown( 17): GUID=d9594d5f-0a6b-6cd2-0dd3-a0e9d11cbd42 (No Format Information found).

    Unknown( 30): GUID=8c4f1b26-e492-807b-7194-cd9ecf5d7e6a (No Format Information found).

    Unknown( 57): GUID=8c4f1b26-e492-807b-7194-cd9ecf5d7e6a (No Format Information found).

    Both reports always display ‘No Format Information found’

    Any help getting this to work would be appreciated.

    Many Thanks,

    Warwick

  11. Ed says:

    winusbtrace view responds:

    C:Usersegreer>winusbtrace view

    Operation Status:       4201L   The instance name passed was not recognized as valid by a WMI data provider.

    The trace log is full of lines like:

    Unknown( 17): GUID=19fcacfa-4892-4a4c-d40b-7377965d7037 (No Format Information found).

    Unknown( 31): GUID=e1464212-0d7b-6456-644c-8f1de14f1927 (No Format Information found).

    Does anyone have any idea what I'm doing wrong?

  12. techie4 says:

    I found you have to run:

    winusbtrace start

    winusbtrace view_realtime

    This will output the informaiton you are looking for. I have no idea what the stuff is supposed to mean that is ouput via view.

    Besides, does anyone have an idea what the number in square bracket at the beginning of the line means?

  13. Eliyas Yakub [MSFT] says:

    It's processor number.

    [CPUNumber]ProcessID.ThreadID::SystemTime –

  14. Dave says:

    Hi,

    I have this almost working on Vista (64-bit)!

    The only problem is that the message guids output by my winusb do not match with any given in the provided win7_winusb.tmf file. This is what causes tracefmt to generate unknown messages. Do I need a different version of winusb to make it compatible with the .tmf file? Or is there another way…?

    Regards

  15. USB Blog says:

    @Dave, The messages are currently decoded only for the Windows 7 RTM and Windows 7 SP1 versions of WinUSB.  "Unknown" is the expected result if your version of WinUSB is different.  Try updating WInUSB using its coinstaller:

    msdn.microsoft.com/…/ff540283%28v=vs.85%29.aspx

  16. Scott says:

    C:win7_winusbtrace_tool>winusbtrace start

    This version of C:win7_winusbtrace_tooltracelog.exe is not compatible with the

    version of Windows you're running. Check your computer's system information to

    see whether you need a x86 (32-bit) or x64 (64-bit) version of the program, and

    then contact the software publisher.

    C:win7_winusbtrace_tool>

    I am running Windows 7 Professional, 64-bit.  Apparently the tools provided via the link you sent do not work correctly with this OS.  Is there a different download for 64-bit Windows 7?

    I am running Windows 7 Professional, 64-bit.  Apparently the tools provided via the link you sent do not work correctly with this OS.  And yes, I did open the command prompt with “Run as administrator”.

    Thanks!

  17. USB Blog says:

    @Scott: If you installed the Win7 WDK, the 64-bit versions of the executable tools can be found in C:WinDDK7600.16385.0toolstracingamd64. Please copy the tools from here to your win7_winusbtrace_tool directory.

  18. PRJ says:

    What would I need to use this WinUSB logging in Windows 8.1?

  19. James says:

    If you are getting something like "Unknown( XX): GUID=___ (No Format Information found).", this means that the tmf file is not found. It took me some time to figure out that _TMF_FILES must be set to the folder path to win7_winusb.tmf, not the file path to it! So something like:

    set _TMF_FILES=C:win7_winusbtrace_tool