Hang when booting with USB Mass Storage device connected.

[dustin howett]

A recent revision fixed the deadlock-on-USB-insert issue, but every time I boot with a flash drive connected, the desktop never starts. I can still get into KDL, though, so it's not hung.

[mmlr]

Could you please enable full USB logging by uncommenting "#define TRACE_USB" in src/add-ons/kernel/bus_managers/usb/usb_p.h and see where it gets stuck. Either by serial output or by enabling on-screen debug output.

[idefix]

I think I have the same problem:

When I boot my computer with an all-in-one usb cardreader connected (without cards inserted), the boot process halts at the fourth icon, see seriallog1.txt.

As soon as I unplug the cardreader the boot process continues, but before showing the desktop it gets into kdl, see seriallog2.txt.

I use the nightly HD images. How can I get only the USB source code and build the driver with tracing enabled?

[idefix]

Booting with cardreader connected

[idefix]

After unplugging cardreader

[mmlr]

Closed bug #2426 as a duplicate of this one.

[mmlr]

Please retest with hrev26082. In case of no response usb_disk should now just time out after a second. Interesting would then be if the device actually recovers and is afterwards usable (if booting works after that change that is).

[idefix]

Tested with hrev26087:
It doesn't hang at boot any more, but the serial log is continually filled with errors, see seriallog3.txt.
Haiku does recognize the cardreader though, see usb_dev_info.txt.

[idefix]

Booting hrev26087

[idefix]

Output of usb_dev_info

[idefix]

When I also connect my Wacom Graphire 2 the error changes, see seriallog4.txt.

[idefix]

Wacom connected -> disconnected -> and connected again

[mmlr]

Replying to idefix:

It doesn't hang at boot any more, but the serial log is continually filled with errors, see seriallog3.txt.
Haiku does recognize the cardreader though, see usb_dev_info.txt.

That looks a bit strange to me. The continued errors are triggered by polling for media changes. This triggers a TEST_UNIT_READY SCSI command on the device, that is apparently not supported or doesn't work when there are no media in the reader. What really surprises me though is that apparently clearing the stall conditions after a mass storage reset results in a stall response. Looking at the tokens in the log the only thing I can guess is that the last phase of the request to clear the halt condition is stalled by the device, as the tokens indicate inbound traffic with no data on endpoint 0, which is only the case for exactly these requests.

As the device info seems to be still readable from usb_dev_info the device and the UHCI controller are in fact not blocked. So the question is, when you insert a card into that card reader, are you able to mount and use it? If it is usable, then I could imagine the device to just stall the clear requests if the bulk pipes aren't actually halted, to indicate that a clear wouldn't have been necessary. In that case they could simply be ignored.

The different errors that get output with the wacom device, they do only show up as soon as you unplug that wacom device again, right? If so that's normal and can be ignored. While the stack and the driver haven't yet noticed the removal of the device they will continue using it resulting in failing transfer descriptors. That stops as soon as the device disconnect is handled. If they come up while the device is plugged in this would indicate some other problem. Again the question, does the wacom device work while you have it plugged?

[idefix]

Replying to mmlr:

As the device info seems to be still readable from usb_dev_info the device and the UHCI controller are in fact not blocked. So the question is, when you insert a card into that card reader, are you able to mount and use it? If it is usable, then I could imagine the device to just stall the clear requests if the bulk pipes aren't actually halted, to indicate that a clear wouldn't have been necessary. In that case they could simply be ignored.

Nope, the card isn't recognised when I put it in. I didn't see any indication of detecting the card in the serial log when I put it in.
When I boot Haiku with the card in the cardreader, I see some detection going on, but in the end I cannot mount it. If you wan't, I can upload a serial log showing this in a couple of hours.

The different errors that get output with the wacom device, they do only show up as soon as you unplug that wacom device again, right? If so that's normal and can be ignored. While the stack and the driver haven't yet noticed the removal of the device they will continue using it resulting in failing transfer descriptors. That stops as soon as the device disconnect is handled. If they come up while the device is plugged in this would indicate some other problem. Again the question, does the wacom device work while you have it plugged?

Yep, my Wacom Graphire 2 keeps working perfectly all the time.
The difference in errors are as follows:
Error with Wacom connected:

usb_disk: sending the command block wrapper failed
USB ControlPipe: timeout waiting for queued request to complete
Last message repeated 2 times.

Error with Wacom disconnected:

usb_disk: sending the command block wrapper failed
usb_uhci: td (0x01a24e00) error: status: 0x394007ff; token: 0xffe80269;

[idefix]

Booting with cardreader connected and SD card inserted

[idefix]

Some detection going on: ​line 345 in seriallog5.txt

[idefix]

Compiled usb and usb_disk with tracing enabled, see seriallog6.txt.

[idefix]

Booting with cardreader connected (tracing enabled)

[mmlr]

Can you retest with a revision >= hrev28934? The stall clearing wouldn't work at all due to a bug fixed in hrev28929, so this has a chance of working now.

[idefix]

Yes, I noticed the changes that you made today so I tested the cardreader with hrev28911 for reference (it didn't work). Will test it again when there's a new image available.

[idefix]

Tested with hrev28974: The seriallog looks the same as hrev28911, only with hrev28974 the sd-card appears in the mount-menu (as 'no-name'). I can mount it and it's folder appears on the desktop (as 'canon-dc'). When I open the folder and open a text-file in that folder, I get KDL'd. See 'Booting with USB cardreader + writelocked SDcard (hrev28974).txt'.

When I boot with the Wacom tablet also attached, the cardreader won't work at all. See 'Booting with USB cardreader + writelocked SDcard (hrev28974) and Wacom.txt'.

Connecting and disconnecting my Wacom changes the error-messages:

usb_disk: operation 0x00 failed at the SCSI level
Last message repeated 11 times.
Last message repeated 12 times.
Last message repeated 12 times.
Last message repeated 9 times.
Last message repeated 6 times.
wacom: add_device() - wacom detected
wacom:  ... success!
void AddOnManager::MessageReceived(BMessage *) what: NMP_
wacom: device_open() open: 2
usb_disk: operation 0x00 failed at the SCSI level
Last message repeated 11 times.
Last message repeated 12 times.
Last message repeated 3 times.
usb_disk: acquire_sem failed while waiting for data transfer
Media removed from /dev/disk/usb/0/0/raw
usb_disk: acquire_sem failed while waiting for data transfer
usb_disk: acquire_sem failed while waiting for data transfer
usb_disk: acquire_sem failed while waiting for data transfer
usb_disk: acquire_sem failed while waiting for data transfer
usb_uhci: td (0x01a21480) error: status: 0x254507ff; token: 0x00e88369;
wacom: interrupt transfer - failure: -2147442668
usb_uhci: td (0x01a214a0) error: status: 0x254507ff; token: 0x00e88369;
usb_uhci: td (0x01a21820) error: status: 0x254507ff; token: 0x00e88369;
[...]
usb_uhci: td (0x01a239a0) error: status: 0x254507ff; token: 0x00e88369;
usb_uhci: td (0x01a239c0) error: status: 0x254507ff; token: 0x00e88369;
usb_disk: operation 0x00 failed at the SCSI level
Last message repeated 2 times.
USB Hub 1: port 1 disabled
wacom: device_removed() open: 1
wacom: device /dev/input/wacom/usb/0 still open -- marked for removal
void AddOnManager::MessageReceived(BMessage *) what: NMP_
usb_disk: operation 0x00 failed at the SCSI level
Last message repeated 11 times.
Last message repeated 12 times.
Last message repeated 12 times.

[idefix]

Booting hrev28974 with cardreader connected and SD card (write locked) inserted.

[idefix]

Booting hrev28974 with cardreader connected and SD card (write locked) inserted. Wacom tablet also connected.

[idefix]

Enabled tracing: 'Booting with USB cardreader + writelocked SDcard (hrev28974) (tracing enabled).txt'

After the computer had completely booted up I connected the Wacom tablet and after 10 seconds I disconnected the tablet.

[idefix]

Booting hrev28974 (tracing enabled) with cardreader connected and SD card (write locked) inserted.

[idefix]

Compiled usb with the new tracing code enabled (hrev29002).
Computer crashes with a page fault, see 'Booting hrev28974 with new tracing code (hrev29002).txt'.

[idefix]

Booting hrev28974 with new tracing code enabled (hrev29002), no USB devices are attached.

[mmlr]

You didn't rebuild all parts. You have to rebuild the host controller drivers as well. Targets are "<usb>uhci", "<usb>ohci" and "<usb>ehci".

[idefix]

Yes, that got it working again: 'Booting hrev28974 with new tracing code (hrev29002) - cardreader connected.zip'

After the computer (with the cardreader connected) had completely booted up, I connected the Wacom tablet and tried to mount the partition. The sd-card appeared in the mount-menu (as 'no-name'), but it didn't appear on the desktop after I clicked on it. When I checked the mount-menu again, the sd-card wasn't listed anymore.

[idefix]

Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. Wacom connected after computer booted up completely. Tried to mount the SD card.

[idefix]

When I don't connect my Wacom tablet, I can succesfully mount the SD card and open a text file from it: 'Booting hrev28974 with new tracing code (hrev29002) - cardreader connected and mounted.zip'

Terminal output: 'Booting hrev28974 with new tracing code (hrev29002) - cardreader connected and mounted (Terminal output).txt'

[idefix]

Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and text file opened.

[idefix]

Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and text file opened - Terminal output.

[idefix]

Opening a larger text file from the SD card disconnects the cardreader: 'Booting hrev28974 with new tracing code (hrev29002) - cardreader connected and mounted (opening larger text file).zip'

Terminal output: 'Booting hrev28974 with new tracing code (hrev29002) - cardreader connected and mounted (opening larger text file) (terminal output).txt'

[idefix]

Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and larger text file opened.

[idefix]

Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and larger text file opened - Terminal output.

[idefix]

After changeset:34915 and changeset:34932 the cardreader is now quite usable when the Wacom tablet is also connected. The only issue now is that when I don't use my pen for ~4 minutes, the cardreader stops working and the serial log shows:

usb_disk: acquire_sem failed while waiting for data transfer
usb_disk: acquire_sem failed while waiting for data transfer
usb_disk: acquire_sem failed while waiting for data transfer

I'm fairly certain that this is caused by the bug described in comment:ticket:4604:13.

[mmlr]

Ok, I'd like to clean this one out. Does the original problem still exist? The issue with the wacom tablet is definitely different in any case and tracked in #4604 or later a follow up of that one, so it isn't relevant for this report.

[idefix]

I can't speak for Dustin, but my computer doesn't hang at boot anymore when my cardreader is connected. So I would be ok with the closing of this ticket.

[mmlr]

Cleaning this one up as stated in comment 22. The original problem should be fixed by now, the other reports are tracked in other tickets and the only other feedback indicates that this ticket can be closed.