Opened 11 years ago

Closed 8 years ago

#2344 closed bug (fixed)

Hang when booting with USB Mass Storage device connected.

Reported by: dustin howett Owned by: mmlr
Priority: normal Milestone: R1
Component: Drivers/USB Version: R1/Development
Keywords: Cc:
Blocked By: Blocking:
Has a Patch: no Platform: x86

Description

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.

Attachments (16)

seriallog1.txt (26.0 KB) - added by idefix 11 years ago.
Booting with cardreader connected
seriallog2.txt (19.0 KB) - added by idefix 11 years ago.
After unplugging cardreader
seriallog3.txt (97.7 KB) - added by idefix 11 years ago.
Booting hrev26087
usb_dev_info.txt (864 bytes) - added by idefix 11 years ago.
Output of usb_dev_info
seriallog4.txt (22.7 KB) - added by idefix 11 years ago.
Wacom connected -> disconnected -> and connected again
seriallog5.txt (64.8 KB) - added by idefix 11 years ago.
Booting with cardreader connected and SD card inserted
seriallog6.txt (113.6 KB) - added by idefix 11 years ago.
Booting with cardreader connected (tracing enabled)
Booting with USB cardreader + writelocked SDcard (r28974).txt (63.9 KB) - added by idefix 11 years ago.
Booting hrev28974 with cardreader connected and SD card (write locked) inserted.
Booting with USB cardreader + writelocked SDcard (r28974) and Wacom.txt (58.3 KB) - added by idefix 11 years ago.
Booting hrev28974 with cardreader connected and SD card (write locked) inserted. Wacom tablet also connected.
Booting with USB cardreader + writelocked SDcard (r28974) (tracing enabled).txt (433.0 KB) - added by idefix 11 years ago.
Booting hrev28974 (tracing enabled) with cardreader connected and SD card (write locked) inserted.
Booting r28974 with new tracing code (r29002).txt (17.8 KB) - added by idefix 11 years ago.
Booting hrev28974 with new tracing code enabled (hrev29002), no USB devices are attached.
Booting r28974 with new tracing code (r29002) - cardreader connected.zip (72.9 KB) - added by idefix 11 years ago.
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.
Booting r28974 with new tracing code (r29002) - cardreader connected and mounted.zip (106.2 KB) - added by idefix 11 years ago.
Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and text file opened.
Booting r28974 with new tracing code (r29002) - cardreader connected and mounted (Terminal output).txt (2.1 KB) - added by idefix 11 years ago.
Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and text file opened - Terminal output.
Booting r28974 with new tracing code (r29002) - cardreader connected and mounted (opening larger text file).zip (15.1 KB) - added by idefix 11 years ago.
Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and larger text file opened.
Booting r28974 with new tracing code (r29002) - cardreader connected and mounted (opening larger text file) (terminal output).txt (1.8 KB) - added by idefix 11 years ago.
Booting hrev28974 (tracing (hrev29002) enabled) with cardreader connected and SD card (write locked) inserted. SD card mounted and larger text file opened - Terminal output.

Download all attachments as: .zip

Change History (40)

comment:1 Changed 11 years ago by 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.

comment:2 Changed 11 years ago by mmlr

Owner: changed from axeld to mmlr
Status: newassigned

comment:3 Changed 11 years ago by 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?

Changed 11 years ago by idefix

Attachment: seriallog1.txt added

Booting with cardreader connected

Changed 11 years ago by idefix

Attachment: seriallog2.txt added

After unplugging cardreader

comment:4 Changed 11 years ago by mmlr

Component: - GeneralDrivers/USB

Closed bug #2426 as a duplicate of this one.

comment:5 Changed 11 years ago by 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).

comment:6 Changed 11 years ago by 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.

Changed 11 years ago by idefix

Attachment: seriallog3.txt added

Booting hrev26087

Changed 11 years ago by idefix

Attachment: usb_dev_info.txt added

Output of usb_dev_info

comment:7 Changed 11 years ago by idefix

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

Changed 11 years ago by idefix

Attachment: seriallog4.txt added

Wacom connected -> disconnected -> and connected again

comment:8 in reply to:  6 ; Changed 11 years ago by 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?

comment:9 in reply to:  8 Changed 11 years ago by 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;

Changed 11 years ago by idefix

Attachment: seriallog5.txt added

Booting with cardreader connected and SD card inserted

comment:10 Changed 11 years ago by idefix

Some detection going on: line 345 in seriallog5.txt

comment:11 Changed 11 years ago by idefix

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

Changed 11 years ago by idefix

Attachment: seriallog6.txt added

Booting with cardreader connected (tracing enabled)

comment:12 Changed 11 years ago by 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.

comment:13 Changed 11 years ago by 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.

comment:14 Changed 11 years ago by 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.

Changed 11 years ago by idefix

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

Changed 11 years ago by idefix

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

comment:15 Changed 11 years ago by 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.

Changed 11 years ago by idefix

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

comment:16 Changed 11 years ago by 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'.

Changed 11 years ago by idefix

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

comment:17 Changed 11 years ago by 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".

comment:18 Changed 11 years ago by 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.

Changed 11 years ago by 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.

comment:19 Changed 11 years ago by 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'

Changed 11 years ago by idefix

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

Changed 11 years ago by idefix

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

comment:20 Changed 11 years ago by 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'

Changed 11 years ago by idefix

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

Changed 11 years ago by 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.

comment:21 Changed 10 years ago by idefix

Version: R1/pre-alpha1R1/Development

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.

comment:22 Changed 9 years ago by 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.

comment:23 Changed 9 years ago by 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.

comment:24 Changed 8 years ago by mmlr

Resolution: fixed
Status: in-progressclosed

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.

Note: See TracTickets for help on using tickets.