Debugging new USB Hub design and suspicious device driver.

[guscrown]

Jan,

This is the enumeration file with no firmware loaded onto the the Reader:

https://www.dropbox.com/s/jlftvic7xg8g5rw/Enumeration%20No%20Firmware.html

Before launching our application that is the state of the reader. Once our application starts, it loads the firmware only the reader and the descriptors change to the ones I attached on my previous post.

I still have not been able to get a failure when the reader is on Stage 1, but I am trying this morning some cycles to confirm this.

[Jan Axelson]

Windows caches descriptors and thus doesn't like it/gets confused if a device re-enumerates with different descriptors but using the same VID and PID.

[guscrown]

That makes sense. But makes me wonder why the Root Hub has never crashed, but external hubs do. This device has been in use for about 10 years or so, but always connected to a root hub on the PC.

[guscrown]

Alright, this is what I have this morning. I believe I have a much better grip on log taking.

From the following log:

This my very small understanding of what is going on:

USBPDO-12 = The Device (it is using the Thesycon usbio.sys driver)
USBPDO-10 = The Hub (it uses the usbhub.sys driver)
USBPDO-4 = The Root Hub
0000006d = The Hub



According to TI, the first two Bulk Transfers you see are OK, and they are 64bytes because it is a Full Speed device. Then I can see some Get Port Status on Port 4, which is where the device is located. I do not know what the Raw data on Seq 0005-0006 is "00 01 01 00".

Full log is here:

https://www.dropbox.com/s/zms8bt20dcmnf3x/OK%20Disconnect%20Firmware%20Loaded.html

Now onto the BAD log:



According to TI, the top two lines after START are incorrect, because the Bulk or Interrupt Transfer of 1024 bytes is for High Speed devices, like I said before, according to them 64 bytes is for Full Speed devices. But I have been unable to confirm this statement.

After that the log gets really crazy, and I am unable to follow it.

What I know so far:

1.- The Hardware analyzer didn't show anything stranger other than the HOST doing a reset immediately after ONE incomplete transaction, whereas in the good disconnection it always does SIX.
2.- I still suspect the device driver, but I am unsure if a device driver has the authority to reset the Upstream of a USB Hub, and why would it do that?

Full bad log here:

https://www.dropbox.com/s/pqm73w9dfquv9dt/NG%20Disconnect%20Firmware%20Loaded.html

Jan,

I am sorry if I have been such a bother, you have been of great help. I believe these last logs should more evidence of what is going on. If you can/want, please take a look at them.

[Barry Twycross]

According to TI, the top two lines after START are incorrect, because the Bulk or Interrupt Transfer of 1024 bytes is for High Speed devices, like I said before, according to them 64 bytes is for Full Speed devices. But I have been unable to confirm this statement.

You can partly confirm it in the spec. Chapter 5 gives an overview of "packet size constraints" for the various transfer types.

1024 bytes is not a valid packet in the USB 1.x spec, or in the 2.x spec for full speed transactions. The largest packet full speed allows is 1023 for Isoc or Interrupt. Bulk is limited to 64 bytes.

[Jan Axelson]

The Raw Data is the port status, see 11.24.2.7 in the USB 2.0 spec.

Do these logs start just after the disconnect? What happened before the disconnect? Was the host requesting 64-byte packets, then switched to 1024 bytes after disconnect? Or?

[guscrown]

Jan,

I start logging and after a few seconds disconnect the cable. Based on the usblyzer logs and the hardware logs, nothing was happening before the disconnect. Just a bunch of NAKs. So according to USBlyzer activity starts on the disconnect.

[Jan Axelson]

Again I have no answers, just questions that may or may not help isolate the problem.

Do you see any problem when you attach and then remove other devices (flash drive, mouse, etc.) from the hub?

When you remove your device, is it using the bootloader firmware or the firmware loaded later? If it's the latter, what host driver does that firmware use?

[guscrown]

No other device connected to the hub causes this error.

When you remove your device, is it using the bootloader firmware or the firmware loaded later?

The firmware loaded later. Problem only happens with Firmware on the device.

If it's the latter, what host driver does that firmware use?

They both use the usbio.sys from Thesycon. The same driver file.

I was looking at the logs this morning and I noticed something: After the host asks for those 1024 bytes, which according to the USB Spec 2.0 is incorrect, because this is a Full Speed HUB, and a Full Speed device, I see a Get port status on Port 4 of the hub (where the device use to be), but there is no reply. After that the host gets a port status (2), which is a status on the Hub itself. To which the hub replys: "01 01" -> A device is present and not in powered-off state, and then a "02 00" which means "Disabled because of a port error condition".

Could there be a correlation between the incorrect 1024 byte buffer and the disabling of the port?

[Jan Axelson]

Yes. However, it's an IN transaction, with no packet size embedded. The host just sends a token packet with the endpoint address and direction, and the device returns the data. On the hardware analyzer log, the last IN transaction is identical except before the device can return NAK, the bus segment resets. So the problem appears to be upstream from the bus segment. Maybe the hub driver chokes on getting an URB requesting a 1024-byte transaction. (A transaction is one packet on the bus. A transfer can consist of multiple transactions.)

So at this point I would suspect the TheSyCon driver. Have you tried contacting them?

 

[guscrown]

Yesterday I sent all this data and conclusions we have gathered to them. I just wanted to be certain that there was no issue with the TI part or my board layout before I threw the ball to their side of the court. Hopefully they can figure something out. As soon as I have a response/solution I will share it with the community.

[Jan Axelson]

Good luck!

[guscrown]

Jan, I have one question for you.

While waiting for the device vendor to answer I decided to look around with the USBlyzer during different operatios of the device and noticed that when firmware is loaded all of the OUT "Bulk or Interrupt Transfer" have a buffer size of 640 bytes. I see others with size 162 bytes. After the firmware has been loaded the "Bulk or Interrupt Transfers" are not 64 bytes long.

But based on the USB Spec 5.8.3 says that for a full speed device the max bulk data payout sizes are 8, 16, 32, or 64. 512 is reserved for high-speed endpoints.

Am I missing something here?

[Jan Axelson]

Transactions are limited to the endpoint's maximum packet size. Transfers can use multiple transactions.

I don't know where USBlyzer is getting the data in the "Request Details" field.  An URB can request a transfer, with a lower-level driver dividing the transfer into transactions. Even so, the 1024-byte URB looks wrong to me in part because the "good" log doesn't have it and also because it immediately precedes the Reset!

http://msdn.microsoft.com/en-us/library/windows/hardware/ff538112%28v=vs.85%29.aspx

[guscrown]

I see. Based on the enumeration descriptors, wMaxPacketSize is set to 0x40h, that means 64 bytes. Something fishy is going on. Either their driver is doing something completely wrong, or USBlyzer is messing up the sniffing. Too bad I can't see this on the hardware sniffer.

But it points more towards something USBlyzer does, take for instances the printer that I am using, it's wMaxPacketSize is also set to 64 bytes, but I see a ton of 4096 Bulk or Interrupt Transfer tokens.