Re: PROBLEM: hotplugging an USB memorystick fails

On 10/17/07, Oliver Neukum <[email protected]> wrote:
> Am Mittwoch 17 Oktober 2007 schrieb I Mouwen:
> > Oct 12 22:18:46 casper kernel: scsi scan: INQUIRY result too short
> > (5), using 36
>
> This shouldn't happen. Enable debugging or better yet, get a usbmon trace.
>
>         Regards
>                 Oliver
>

Here's the kernel log with debugging enabled. This is when I insert
the memory stick after booting.


Regards,

Iwan Mouwen


Oct 17 21:13:34 casper kernel: usb usb2: usb resume
Oct 17 21:13:34 casper kernel: ehci_hcd 0000:00:02.1: resume root hub
Oct 17 21:13:34 casper kernel: hub 2-0:1.0: hub_resume
Oct 17 21:13:34 casper kernel: hub 2-0:1.0: state 7 ports 10 chg 0000 evt 0000
Oct 17 21:13:34 casper kernel: ehci_hcd 0000:00:02.1: GetStatus port 5
status 001803 POWER sig=j CSC CONNECT
Oct 17 21:13:34 casper kernel: hub 2-0:1.0: port 5, status 0501,
change 0001, 480 Mb/s
Oct 17 21:13:34 casper kernel: hub 2-0:1.0: debounce: port 5: total
100ms stable 100ms status 0x501
Oct 17 21:13:34 casper kernel: ehci_hcd 0000:00:02.1: port 5 high speed
Oct 17 21:13:34 casper kernel: ehci_hcd 0000:00:02.1: GetStatus port 5
status 001005 POWER sig=se0 PE CONNECT
Oct 17 21:13:35 casper kernel: usb 2-5: new high speed USB device
using ehci_hcd and address 5
Oct 17 21:13:35 casper kernel: ehci_hcd 0000:00:02.1: port 5 high speed
Oct 17 21:13:35 casper kernel: ehci_hcd 0000:00:02.1: GetStatus port 5
status 001005 POWER sig=se0 PE CONNECT
Oct 17 21:13:35 casper kernel: usb 2-5: skipped 1 descriptor after endpoint
Oct 17 21:13:35 casper kernel: usb 2-5: default language 0x0409
Oct 17 21:13:35 casper kernel: usb 2-5: new device strings: Mfr=1,
Product=3, SerialNumber=0
Oct 17 21:13:35 casper kernel: usb 2-5: Product: USB Embedded Hub
Oct 17 21:13:35 casper kernel: usb 2-5: Manufacturer: TSE Inc.
Oct 17 21:13:35 casper kernel: usb 2-5: uevent
Oct 17 21:13:35 casper kernel: usb 2-5: usb_probe_device
Oct 17 21:13:35 casper kernel: usb 2-5: configuration #1 chosen from 1 choice
Oct 17 21:13:35 casper kernel: usb 2-5: adding 2-5:1.0 (config #1, interface 0)
Oct 17 21:13:35 casper kernel: usb 2-5:1.0: uevent
Oct 17 21:13:35 casper kernel: usb 2-5:1.0: uevent
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: usb_probe_interface
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: usb_probe_interface - got id
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: USB hub found
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: 1 port detected
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: compound device; port
removable status: F
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: individual port power switching
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: individual port
over-current protection
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: Single TT
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: TT requires at most 8 FS
bit times (666 ns)
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: power on to power good time: 100ms
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: local power source is lost
(inactive)
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: enabling power on all ports
Oct 17 21:13:35 casper kernel: usb 2-5: link
qh256-0001/ffff81003e40b140 start 255 [1/0 us]
Oct 17 21:13:35 casper kernel: drivers/usb/core/inode.c: creating file '005'
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: state 7 ports 1 chg 0000 evt 0000
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: port 1, status 0501,
change 0001, 480 Mb/s
Oct 17 21:13:35 casper kernel: hub 2-5:1.0: debounce: port 1: total
100ms stable 100ms status 0x501
Oct 17 21:13:35 casper kernel: usb 2-5.1: new high speed USB device
using ehci_hcd and address 6
Oct 17 21:13:35 casper kernel: usb 2-5.1: default language 0x0409
Oct 17 21:13:35 casper kernel: usb 2-5.1: new device strings: Mfr=1,
Product=4, SerialNumber=0
Oct 17 21:13:35 casper kernel: usb 2-5.1: Product: USB Mass Storage Device
Oct 17 21:13:35 casper kernel: usb 2-5.1: Manufacturer: TSE Inc.
Oct 17 21:13:35 casper kernel: usb 2-5.1: uevent
Oct 17 21:13:35 casper kernel: usb 2-5.1: usb_probe_device
Oct 17 21:13:35 casper kernel: usb 2-5.1: configuration #1 chosen from 1 choice
Oct 17 21:13:35 casper kernel: usb 2-5.1: adding 2-5.1:1.0 (config #1,
interface 0)
Oct 17 21:13:35 casper kernel: usb 2-5.1:1.0: uevent
Oct 17 21:13:35 casper kernel: usb 2-5.1:1.0: uevent
Oct 17 21:13:35 casper kernel: drivers/usb/core/inode.c: creating file '006'
Oct 17 21:13:35 casper kernel: Initializing USB Mass Storage driver...
Oct 17 21:13:35 casper kernel: usb-storage 2-5.1:1.0: usb_probe_interface
Oct 17 21:13:35 casper kernel: usb-storage 2-5.1:1.0:
usb_probe_interface - got id
Oct 17 21:13:35 casper kernel: usb-storage: USB Mass Storage device detected
Oct 17 21:13:35 casper kernel: usb-storage: -- associate_dev
Oct 17 21:13:35 casper kernel: usb-storage: Vendor: 0x13e0, Product:
0x2517, Revision: 0x0100
Oct 17 21:13:35 casper kernel: usb-storage: Interface Subclass: 0x06,
Protocol: 0x50
Oct 17 21:13:35 casper kernel: usb-storage: Transport: Bulk
Oct 17 21:13:35 casper kernel: usb-storage: Protocol: Transparent SCSI
Oct 17 21:13:35 casper kernel: scsi4 : SCSI emulation for USB Mass
Storage devices
Oct 17 21:13:35 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:35 casper kernel: usb-storage: device found at 6
Oct 17 21:13:35 casper kernel: usb-storage: waiting for device to
settle before scanning
Oct 17 21:13:35 casper kernel: usbcore: registered new interface
driver usb-storage
Oct 17 21:13:35 casper kernel: USB Mass Storage support registered.
Oct 17 21:13:40 casper kernel: usb-storage: usb_stor_control_msg:
rq=fe rqtype=a1 value=0000 index=00 len=1
Oct 17 21:13:40 casper kernel: usb-storage: GetMaxLUN command result
is 1, data is 0
Oct 17 21:13:40 casper kernel: usb-storage: device scan complete
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Command INQUIRY (6 bytes)
Oct 17 21:13:40 casper kernel: usb-storage:  12 00 00 00 24 00
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Command S 0x43425355
T 0x1 L 36 F 128 Trg 0 LUN 0 CL 6
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 31/31
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk command transfer result=0
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_sglist: xfer 36 bytes, 1 entries
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 36/36
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk data transfer result 0x0
Oct 17 21:13:40 casper kernel: usb-storage: Attempting to get CSW...
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 13/13
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk status result = 0
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Status S 0x53425355 T
0x1 R 0 Stat 0x0
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x0
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: scsi scan: INQUIRY result too short (5), using 36
Oct 17 21:13:40 casper kernel: scsi 4:0:0:0: Direct-Access     USB
 2.0 Flash Drive  1.00 PQ: 0 ANSI: 0
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad LUN (0:1)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (1:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (2:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (3:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (4:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (5:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (6:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Bad target number (7:0)
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x40000
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Command TEST_UNIT_READY (6 bytes)
Oct 17 21:13:40 casper kernel: usb-storage:  00 00 00 00 00 00
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Command S 0x43425355
T 0x2 L 0 F 0 Trg 0 LUN 0 CL 6
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 31/31
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk command transfer result=0
Oct 17 21:13:40 casper kernel: usb-storage: Attempting to get CSW...
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 13/13
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk status result = 0
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Status S 0x53425355 T
0x2 R 0 Stat 0x1
Oct 17 21:13:40 casper kernel: usb-storage: -- transport indicates
command failure
Oct 17 21:13:40 casper kernel: usb-storage: Issuing auto-REQUEST_SENSE
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Command S 0x43425355
T 0x3 L 18 F 128 Trg 0 LUN 0 CL 6
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 31/31
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk command transfer result=0
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 18 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 18/18
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk data transfer result 0x0
Oct 17 21:13:40 casper kernel: usb-storage: Attempting to get CSW...
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 13/13
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk status result = 0
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Status S 0x53425355 T
0x3 R 0 Stat 0x0
Oct 17 21:13:40 casper kernel: usb-storage: -- Result from auto-sense is 0
Oct 17 21:13:40 casper kernel: usb-storage: -- code: 0x70, key: 0x6,
ASC: 0x3a, ASCQ: 0x0
Oct 17 21:13:40 casper kernel: usb-storage: Unit Attention: Medium not present
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x2
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: sd 4:0:0:0: [sda] Attached SCSI disk
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Command INQUIRY (6 bytes)
Oct 17 21:13:40 casper kernel: usb-storage:  12 00 00 00 fe 00
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Command S 0x43425355
T 0x4 L 254 F 128 Trg 0 LUN 0 CL 6
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 31/31
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk command transfer result=0
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_sglist: xfer 254 bytes, 1 entries
Oct 17 21:13:40 casper kernel: usb-storage: Status code -121; transferred 36/254
Oct 17 21:13:40 casper kernel: usb-storage: -- short read transfer
Oct 17 21:13:40 casper kernel: usb-storage: Bulk data transfer result 0x1
Oct 17 21:13:40 casper kernel: usb-storage: Attempting to get CSW...
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 13/13
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk status result = 0
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Status S 0x53425355 T
0x4 R 218 Stat 0x0
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x0
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
Oct 17 21:13:40 casper kernel: usb-storage: Command INQUIRY (6 bytes)
Oct 17 21:13:40 casper kernel: usb-storage:  12 01 00 00 fe 00
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Command S 0x43425355
T 0x5 L 254 F 128 Trg 0 LUN 0 CL 6
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 31/31
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk command transfer result=0
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_sglist: xfer 254 bytes, 1 entries
Oct 17 21:13:40 casper kernel: usb-storage: Status code -121; transferred 36/254
Oct 17 21:13:40 casper kernel: usb-storage: -- short read transfer
Oct 17 21:13:40 casper kernel: usb-storage: Bulk data transfer result 0x1
Oct 17 21:13:40 casper kernel: usb-storage: Attempting to get CSW...
Oct 17 21:13:40 casper kernel: usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Oct 17 21:13:40 casper kernel: usb-storage: Status code 0; transferred 13/13
Oct 17 21:13:40 casper kernel: usb-storage: -- transfer complete
Oct 17 21:13:40 casper kernel: usb-storage: Bulk status result = 0
Oct 17 21:13:40 casper kernel: usb-storage: Bulk Status S 0x53425355 T
0x5 R 218 Stat 0x0
Oct 17 21:13:40 casper kernel: usb-storage: scsi cmd done, result=0x0
Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.

-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
[email protected]
To unsubscribe, use the last form field at:
https://lists.sourceforge.net/lists/listinfo/linux-usb-devel