On Sun, Sep 21, 2003 at 06:41:43PM -0700, Linus Torvalds wrote: > Ideas? Anything that stands out except for the "babble" thing?
So, here is what I see in the log...
> hub 2-0:0: new USB device on port 1, assigned address 2
> usb-storage: USB Mass Storage device detected
> usb-storage: act_altsetting is 0, id_index is 76
The device has an unusual device list entry.
> usb-storage: -- associate_dev
> usb-storage: Transport: Bulk
> usb-storage: Protocol: Transparent SCSI
> usb-storage: Endpoints: In: 0xdd6baf40 Out: 0xdd6baf54 Int: 0x00000000 (Period 0)
> usb-storage: usb_stor_control_msg: rq=fe rqtype=a1 value=0000 index=00 len=1
> usb-storage: GetMaxLUN command result is -32, data is 0
Single LUN device.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command INQUIRY (6 bytes)
> usb-storage: 12 00 00 00 24 00
> usb-storage: Bulk Command S 0x43425355 T 0x1 L 36 F 128 Trg 0 LUN 0 CL 6
> usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
> usb-storage: Status code 0; transferred 31/31
> usb-storage: -- transfer complete
> usb-storage: Bulk command transfer result=0
> usb-storage: usb_stor_bulk_transfer_buf: xfer 36 bytes
> usb-storage: Status code 0; transferred 36/36
> usb-storage: -- transfer complete
> usb-storage: Bulk data transfer result 0x0
> usb-storage: Attempting to get CSW...
> usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
> usb-storage: Status code 0; transferred 13/13
> usb-storage: -- transfer complete
> usb-storage: Bulk status result = 0
> usb-storage: Bulk Status S 0x53425355 T 0x1 R 0 Stat 0x0
> usb-storage: Fixing INQUIRY data to show SCSI rev 2 - was 0
> usb-storage: scsi cmd done, result=0x0
> usb-storage: *** thread sleeping.
Normal INQUIRY for 36 bytes -- all good so far.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command INQUIRY (6 bytes)
> usb-storage: 12 00 00 00 25 00
> usb-storage: Bulk Command S 0x43425355 T 0x2 L 37 F 128 Trg 0 LUN 0 CL 6
> usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
> usb-storage: Status code 0; transferred 31/31
> usb-storage: -- transfer complete
> usb-storage: Bulk command transfer result=0
> usb-storage: usb_stor_bulk_transfer_buf: xfer 37 bytes
> usb-storage: Status code 0; transferred 36/37
> usb-storage: -- short transfer
> usb-storage: Bulk data transfer result 0x1
> usb-storage: Attempting to get CSW...
> usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
> usb-storage: Status code 0; transferred 13/13
> usb-storage: -- transfer complete
> usb-storage: Bulk status result = 0
> usb-storage: Bulk Status S 0x53425355 T 0x2 R 0 Stat 0x0
> usb-storage: Fixing INQUIRY data to show SCSI rev 2 - was 0
> usb-storage: scsi cmd done, result=0x0
> usb-storage: *** thread sleeping.
Normal INQUIRY for 37 bytes -- all good so far.
> Vendor: TOSHIBA Model: THNCF1G02MA Rev: 0811
> Type: Direct-Access ANSI SCSI revision: 02
Direct-access.... everything from here down is likely from sd.c
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command TEST_UNIT_READY (6 bytes)
Normal TUR -- device is ready for commands.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command READ_CAPACITY (10 bytes)
>
> SCSI device sda: 2000880 512-byte hdwr sectors (1024 MB)
Normal READ_CAPACITY -- is that size correct?
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command MODE_SENSE_10 (10 bytes)
> usb-storage: 5a 00 3f 00 00 00 00 00 08 00
>
> sda: Write Protect is off
> sda: Mode Sense: 06 00 00 00
MODE_SENSE_10 for all pages (0x3f) worked, which sometimes I think is a
small miracle.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command MODE_SENSE_10 (10 bytes)
> usb-storage: 5a 00 08 00 00 00 00 00 08 00
Odd... why do we ask for the first 8 bytes of page 8? The header alone is
8 bytes.... anyway, the response looks good.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command MODE_SENSE_10 (10 bytes)
> usb-storage: 5a 00 08 00 00 00 00 00 80 00
> usb-storage: Bulk Command S 0x43425355 T 0x7 L 128 F 128 Trg 0 LUN 0 CL 10
> usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
> usb-storage: Status code 0; transferred 31/31
> usb-storage: -- transfer complete
> usb-storage: Bulk command transfer result=0
> usb-storage: usb_stor_bulk_transfer_buf: xfer 128 bytes
> usb-storage: Status code -75; transferred 64/128
> usb-storage: -- babble
> usb-storage: Bulk data transfer result 0x3
The last 3 lines are the first sign of trouble. As previously discussed, I
don't see how a BABBLE error here is possible from a technical point of
view.
> usb-storage: Attempting to get CSW...
> usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
> usb-storage: Status code 0; transferred 0/13
> usb-storage: -- short transfer
> usb-storage: Bulk status result = 1
More strangeness -- the device ACKed a transfer with a 0-byte packet?
That's very strange....
> usb-storage: -- transport indicates error, resetting
> usb-storage: usb_stor_Bulk_reset called
> usb-storage: usb_stor_control_msg: rq=ff rqtype=21 value=0000 index=00 len=0
> usb-storage: Soft reset: clearing bulk-in endpoint halt
> usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=81 len=0
> usb-storage: usb_stor_clear_halt: result = 0
> usb-storage: Soft reset: clearing bulk-out endpoint halt
> usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=02 len=0
> usb-storage: usb_stor_clear_halt: result = 0
> usb-storage: Soft reset done
This is the first error-recovery protocol in action. We sent a reset
request, and the device appears to be responding to our requests. At
least, it's ACKing them.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command MODE_SENSE_10 (10 bytes)
> usb-storage: 5a 00 08 00 00 00 00 00 80 00
> usb-storage: Bulk Command S 0x43425355 T 0x8 L 128 F 128 Trg 0 LUN 0 CL 10
> usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
> usb-storage: Status code 0; transferred 31/31
> usb-storage: -- transfer complete
> usb-storage: Bulk command transfer result=0
> usb-storage: usb_stor_bulk_transfer_buf: xfer 128 bytes
> usb-storage: Status code -75; transferred 64/128
> usb-storage: -- babble
> usb-storage: Bulk data transfer result 0x3
Since we reset fully, we now try the command again. We get into the same
babble problem again.
> usb-storage: Attempting to get CSW...
> usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
> usb-storage: Status code 0; transferred 13/13
> usb-storage: -- transfer complete
> usb-storage: Bulk status result = 0
> usb-storage: Bulk Status S 0x53425355 T 0x8 R 0 Stat 0x0
> usb-storage: scsi cmd done, result=0x2
> usb-storage: *** thread sleeping.
But, this time, instead of a 0-byte packet, we actually got the data we
CSW to complete the transaction. Note that the TAG matches -- we're
definately in phase with the device. But it thinks the world is good (stat
0), when it's really not.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command TEST_UNIT_READY (6 bytes)
> usb-storage: 00 00 00 00 00 00
> usb-storage: Bulk Command S 0x43425355 T 0x9 L 0 F 0 Trg 0 LUN 0 CL 6
> usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
> usb-storage: Status code 0; transferred 31/31
> usb-storage: -- transfer complete
> usb-storage: Bulk command transfer result=0
> usb-storage: Attempting to get CSW...
> usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
> usb-storage: command_abort called
And now we're toast again. We send a TUR, but the device never answers.
The timeout is hit, and we go into the abort paths.
> usb-storage: usb_stor_stop_transport called
> usb-storage: -- cancelling URB
> usb-storage: Status code -104; transferred 0/13
> usb-storage: -- transfer cancelled
We abort the transfer in progress -- that works.
> usb-storage: Bulk status result = 4
> usb-storage: -- command was aborted
> usb-storage: usb_stor_Bulk_reset called
> usb-storage: usb_stor_control_msg: rq=ff rqtype=21 value=0000 index=00 len=0
We try a reset procedure again....
> usb-storage: Timeout -- cancelling URB
> usb-storage: Soft reset failed: -104
But it doesn't work this time....
> usb-storage: scsi command aborted
> usb-storage: *** thread sleeping.
> usb-storage: queuecommand called
> usb-storage: *** thread awakened.
> usb-storage: Command TEST_UNIT_READY (6 bytes)
> usb-storage: 00 00 00 00 00 00
> usb-storage: Bulk Command S 0x43425355 T 0x9 L 0 F 0 Trg 0 LUN 0 CL 6
> usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
> usb-storage: Status code 0; transferred 31/31
> usb-storage: -- transfer complete
> usb-storage: Bulk command transfer result=0
> usb-storage: Attempting to get CSW...
> usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
> usb-storage: command_abort called
> usb-storage: usb_stor_stop_transport called
> usb-storage: -- cancelling URB
> usb-storage: Status code -104; transferred 0/13
> usb-storage: -- transfer cancelled
> usb-storage: Bulk status result = 4
> usb-storage: -- command was aborted
> usb-storage: usb_stor_Bulk_reset called
> usb-storage: usb_stor_control_msg: rq=ff rqtype=21 value=0000 index=00 len=0
> usb-storage: Timeout -- cancelling URB
> usb-storage: Soft reset failed: -104
> usb-storage: scsi command aborted
> usb-storage: *** thread sleeping.
Lather, rince, repeat....
> usb-storage: device_reset called
> usb-storage: usb_stor_Bulk_reset called
> usb-storage: usb_stor_control_msg: rq=ff rqtype=21 value=0000 index=00 len=0
> usb-storage: Timeout -- cancelling URB
> usb-storage: Soft reset failed: -104
> usb-storage: bus_reset called
Now, we try a higher-level of reset. This code is supposed to issue a port
reset to the device -- this should always succeed, regardless of the state
of the device. The state of the HC and HCD, however, could create a
problem....
Why this now just stops is a mystery to me...
> scsi_eh_0 D E493D4A7 9167888 1480 1 1484 1479 (L-TLB)
> d3b07e0c 00000046 dde96fe0 e493d4a7 00000049 d3b07df4 c011ee86 ddb8df38
> 00000001 00000000 e493d4a7 00000049 dde96fe0 00004940 e493f093 00000049
> d3247580 c04eab6c fffeffff dd4dc0e4 d3b07e54 c023d36d ffffffb7 00000086
> Call Trace:
> [<c011ee86>] __wake_up_common+0x38/0x57
> [<c023d36d>] rwsem_down_read_failed+0x129/0x24c
> [<c0125e82>] printk+0x27b/0x3f8
> [<c033145a>] .text.lock.hub+0x75/0x93
> [<c03446c6>] bus_reset+0x233/0x2ac
> [<c02efa92>] scsi_try_bus_reset+0xd1/0x21e
> [<c02efe82>] scsi_eh_bus_reset+0x85/0x130
> [<c02ef59e>] scsi_eh_tur+0x9e/0xcb
> [<c02f0417>] scsi_eh_ready_devs+0x49/0x74
> [<c02f060a>] scsi_unjam_host+0x158/0x1e5
> [<c011ee20>] default_wake_function+0x0/0x2e
> [<c02f091d>] scsi_error_handler+0x286/0x2c2
> [<c02f0697>] scsi_error_handler+0x0/0x2c2
> [<c01082a5>] kernel_thread_helper+0x5/0xb
If I read this correctly (and that's a _big_ if), the bus_reset function is
stuck waiting on a semaphore... maybe? We could be stuck trying to take
us->dev_semaphore (which is almost impossible, given where we are), or
we're waiting for the completion function from the port reset request. My
guess is the latter
In short, all this points to some sort of HCD problem....
Matt
--
Matthew Dharm Home: [EMAIL PROTECTED]
Maintainer, Linux USB Mass Storage Driver
G: Money isn't everything, A.J.
AJ: Who convinced you of that?
G: The Chief, at my last salary review.
-- Mike and Greg
User Friendly, 11/3/1998
pgp00000.pgp
Description: PGP signature
