Ok. I finally was able to compile a kernel with debug messages on.
So here's what I'm doing. I'm plugging in the device and hotplug automatically
detects it [see connect.log as attached]
Then I mount it and start copying files. Which involves a lot of message like
this:
Apr 18 20:04:24 einstein usb-storage: queuecommand called
Apr 18 20:04:24 einstein usb-storage: *** thread awakened.
Apr 18 20:04:24 einstein usb-storage: Command WRITE_10 (10 bytes)
Apr 18 20:04:24 einstein usb-storage: 2a 00 00 a2 7f d3 00 00 80 00
Apr 18 20:04:24 einstein usb-storage: Bulk Command S 0x43425355 T 0x966 L
65536 F 0 Trg 0 LUN 0 CL 10
Apr 18 20:04:24 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31
bytes
Apr 18 20:04:24 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:04:24 einstein usb-storage: -- transfer complete
Apr 18 20:04:24 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:04:24 einstein usb-storage: usb_stor_bulk_transfer_sglist: xfer
65536 bytes, 4 entries
Apr 18 20:04:24 einstein usb-storage: Status code 0; transferred 65536/65536
Apr 18 20:04:24 einstein usb-storage: -- transfer complete
Apr 18 20:04:24 einstein usb-storage: Bulk data transfer result 0x0
Apr 18 20:04:24 einstein usb-storage: Attempting to get CSW...
Apr 18 20:04:24 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13
bytes
Apr 18 20:04:24 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:04:24 einstein usb-storage: -- transfer complete
Apr 18 20:04:24 einstein usb-storage: Bulk status result = 0
Apr 18 20:04:24 einstein usb-storage: Bulk Status S 0x53425355 T 0x966 R 0
Stat 0x0
Apr 18 20:04:24 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:04:24 einstein usb-storage: *** thread sleeping.
Apr 18 20:04:24 einstein usb-storage: queuecommand called
Then after so many files processed, the cp command locks up. This is what
usb-storage says:
usb-storage: queuecommand called
usb-storage: *** thread awakened.
usb-storage: Command WRITE_10 (10 bytes)
usb-storage: 2a 00 00 a4 d7 53 00 00 80 00
usb-storage: Bulk Command S 0x43425355 T 0xa79 L 65536 F 0 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_sglist: xfer 65536 bytes, 10 entries
usb-storage: command_abort called
usb-storage: usb_stor_stop_transport called
usb-storage: -- cancelling sg request
A couple of things I noticed:
- I still can browse through the mounted directory. Although it lists files
which are not completely transferred (if I disconnect the device, they're not
showing up in the device itself)
- I cannot umount it. but when I disconnect the cable I still get these
messages:
hub 3-0:1.0: state 5 ports 5 chg 0000 evt 0020
ehci_hcd 0000:01:07.2: GetStatus port 5 status 001002 POWER sig=se0 CSC
hub 3-0:1.0: port 5, status 0100, change 0001, 12 Mb/s
usb 3-5: USB disconnect, address 3
usb 3-5: usb_disable_device nuking all URBs
- The following related processes seem to be sleeping:
4825 root 15 0 0 0 0 D 0.0 0.0 0:00.00 scsi_eh_1
4826 root 15 0 0 0 0 D 0.0 0.0 0:00.20 usb-storage
4939 root 17 0 3540 588 500 D 0.0 0.1 0:00.00 cp
The full log file is somewhat large. I hope I've provided everything you need.
Let me know If I need to turn more debugging on or not. Or send the full log
file.
Sander
On Monday 28 March 2005 07:22, Alan Stern wrote:
> On Sun, 27 Mar 2005, Sander Jansen wrote:
> > Hi,
> >
> > I'm trying to get my iriver hp120 to work with EHCI. It already seem to
> > work with just the OHCI driver although quit slow ofcourse. Basically
> > the whole usb system seems to lockup whenever I start transfering files
> > to my iriver. The rest of the system is not locked up btw. Now I have
> > the feeling that this 'bug' might already been fixed, though I'm not sure
> > if it made it to the official kernel or not..I'm running Linux 2.6.11 on
> > a nforce motherboard with an usb2 pci extension card.
> >
> > I don't get any error or debug messages from usb-massstorage. Any clues
> > on how to enable those would be nice.
>
> You have to turn on the USB Mass Storage verbose debugging option in the
> kernel configuration (CONFIG_USB_STORAGE_DEBUG) and rebuild the driver.
> Also make sure that you either read the debugging messages with dmesg or
> else configure /etc/syslog.conf to capture the kernel's debug-level
> messages.
>
> > I know there were bugs related to the device itself not reporting the
> > correct size of the harddrive. Assuming these are fixed (since usb 1.1
> > seem to work without problems), might it be related to usb2?
>
> Maybe. It's impossible to say without more information.
>
> Alan Stern
>
>
>
> -------------------------------------------------------
> SF email is sponsored by - The IT Product Guide
> Read honest & candid reviews on hundreds of IT Products from real users.
> Discover which products truly live up to the hype. Start reading now.
> http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click
> _______________________________________________
> [email protected]
> To unsubscribe, use the last form field at:
> https://lists.sourceforge.net/lists/listinfo/linux-usb-users
Apr 18 20:02:09 einstein usb 3-5: new device strings: Mfr=73, Product=93, SerialNumber=115
Apr 18 20:02:09 einstein usb 3-5: default language 0x0409
Apr 18 20:02:09 einstein usb 3-5: Product: iRiver iHP-100 Series
Apr 18 20:02:09 einstein usb 3-5: Manufacturer: iRiver
Apr 18 20:02:09 einstein usb 3-5: SerialNumber: 0123456789AB
Apr 18 20:02:09 einstein usb 3-5: hotplug
Apr 18 20:02:09 einstein usb 3-5: adding 3-5:2.0 (config #2, interface 0)
Apr 18 20:02:09 einstein usb 3-5:2.0: hotplug
Apr 18 20:02:10 einstein Initializing USB Mass Storage driver...
Apr 18 20:02:10 einstein usb-storage 3-5:2.0: usb_probe_interface
Apr 18 20:02:10 einstein usb-storage 3-5:2.0: usb_probe_interface - got id
Apr 18 20:02:10 einstein usb-storage: USB Mass Storage device detected
Apr 18 20:02:10 einstein usb-storage: -- associate_dev
Apr 18 20:02:10 einstein usb-storage: Vendor: 0x1006, Product: 0x3002, Revision: 0x0100
Apr 18 20:02:10 einstein usb-storage: Interface Subclass: 0x06, Protocol: 0x50
Apr 18 20:02:10 einstein usb-storage: Vendor: iRiver , Product: iRiver iHP-100 Series
Apr 18 20:02:10 einstein usb-storage: Transport: Bulk
Apr 18 20:02:10 einstein usb-storage: Protocol: Transparent SCSI
Apr 18 20:02:10 einstein usb-storage: usb_stor_control_msg: rq=fe rqtype=a1 value=0000 index=00 len=1
Apr 18 20:02:10 einstein usb-storage: GetMaxLUN command result is 1, data is 0
Apr 18 20:02:10 einstein scsi0 : SCSI emulation for USB Mass Storage devices
Apr 18 20:02:10 einstein usbcore: registered new driver usb-storage
Apr 18 20:02:10 einstein USB Mass Storage support registered.
Apr 18 20:02:10 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:10 einstein usb-storage: device found at 2
Apr 18 20:02:10 einstein usb-storage: waiting for device to settle before scanning
Apr 18 20:02:15 einstein usb-storage: queuecommand called
Apr 18 20:02:15 einstein usb-storage: *** thread awakened.
Apr 18 20:02:15 einstein usb-storage: Command INQUIRY (6 bytes)
Apr 18 20:02:15 einstein usb-storage: 12 00 00 00 24 00
Apr 18 20:02:15 einstein usb-storage: Bulk Command S 0x43425355 T 0x1 L 36 F 128 Trg 0 LUN 0 CL 6
Apr 18 20:02:15 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Apr 18 20:02:15 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:02:15 einstein usb-storage: -- transfer complete
Apr 18 20:02:15 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:02:15 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 36 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 36/36
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk data transfer result 0x0
Apr 18 20:02:16 einstein usb-storage: Attempting to get CSW...
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk status result = 0
Apr 18 20:02:16 einstein usb-storage: Bulk Status S 0x53425355 T 0x1 R 0 Stat 0x0
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein Vendor: TOSHIBA Model: MK2004GAL Rev: JC10
Apr 18 20:02:16 einstein Type: Direct-Access ANSI SCSI revision: 00
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Command TEST_UNIT_READY (6 bytes)
Apr 18 20:02:16 einstein usb-storage: 00 00 00 00 00 00
Apr 18 20:02:16 einstein usb-storage: Bulk Command S 0x43425355 T 0x2 L 0 F 0 Trg 0 LUN 0 CL 6
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:02:16 einstein usb-storage: Attempting to get CSW...
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk status result = 0
Apr 18 20:02:16 einstein usb-storage: Bulk Status S 0x53425355 T 0x2 R 0 Stat 0x0
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Command READ_CAPACITY (10 bytes)
Apr 18 20:02:16 einstein usb-storage: 25 00 00 00 00 00 00 00 00 00
Apr 18 20:02:16 einstein usb-storage: Bulk Command S 0x43425355 T 0x3 L 8 F 128 Trg 0 LUN 0 CL 10
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 8 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 8/8
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk data transfer result 0x0
Apr 18 20:02:16 einstein usb-storage: Attempting to get CSW...
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk status result = 0
Apr 18 20:02:16 einstein usb-storage: Bulk Status S 0x53425355 T 0x3 R 0 Stat 0x0
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein SCSI device sda: 39063024 512-byte hdwr sectors (20000 MB)
Apr 18 20:02:16 einstein sda: assuming drive cache: write through
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Command TEST_UNIT_READY (6 bytes)
Apr 18 20:02:16 einstein usb-storage: 00 00 00 00 00 00
Apr 18 20:02:16 einstein usb-storage: Bulk Command S 0x43425355 T 0x4 L 0 F 0 Trg 0 LUN 0 CL 6
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:02:16 einstein usb-storage: Attempting to get CSW...
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk status result = 0
Apr 18 20:02:16 einstein usb-storage: Bulk Status S 0x53425355 T 0x4 R 0 Stat 0x0
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Command READ_CAPACITY (10 bytes)
Apr 18 20:02:16 einstein usb-storage: 25 00 00 00 00 00 00 00 00 00
Apr 18 20:02:16 einstein usb-storage: Bulk Command S 0x43425355 T 0x5 L 8 F 128 Trg 0 LUN 0 CL 10
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 8 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 8/8
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk data transfer result 0x0
Apr 18 20:02:16 einstein usb-storage: Attempting to get CSW...
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk status result = 0
Apr 18 20:02:16 einstein usb-storage: Bulk Status S 0x53425355 T 0x5 R 0 Stat 0x0
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein SCSI device sda: 39063024 512-byte hdwr sectors (20000 MB)
Apr 18 20:02:16 einstein sda: assuming drive cache: write through
Apr 18 20:02:16 einstein /dev/scsi/host0/bus0/target0/lun0:<7>usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Command READ_10 (10 bytes)
Apr 18 20:02:16 einstein usb-storage: 28 00 00 00 00 00 00 00 08 00
Apr 18 20:02:16 einstein usb-storage: Bulk Command S 0x43425355 T 0x6 L 4096 F 128 Trg 0 LUN 0 CL 10
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 31/31
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk command transfer result=0
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_sglist: xfer 4096 bytes, 1 entries
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 4096/4096
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk data transfer result 0x0
Apr 18 20:02:16 einstein usb-storage: Attempting to get CSW...
Apr 18 20:02:16 einstein usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Apr 18 20:02:16 einstein usb-storage: Status code 0; transferred 13/13
Apr 18 20:02:16 einstein usb-storage: -- transfer complete
Apr 18 20:02:16 einstein usb-storage: Bulk status result = 0
Apr 18 20:02:16 einstein usb-storage: Bulk Status S 0x53425355 T 0x6 R 0 Stat 0x0
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x0
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein p1
Apr 18 20:02:16 einstein Attached scsi disk sda at scsi0, channel 0, id 0, lun 0
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad LUN (0:1)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (1:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (2:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (3:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (4:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (5:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (6:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: queuecommand called
Apr 18 20:02:16 einstein usb-storage: *** thread awakened.
Apr 18 20:02:16 einstein usb-storage: Bad target number (7:0)
Apr 18 20:02:16 einstein usb-storage: scsi cmd done, result=0x40000
Apr 18 20:02:16 einstein usb-storage: *** thread sleeping.
Apr 18 20:02:16 einstein usb-storage: device scan complete
Apr 18 20:03:29 einstein usb-storage: queuecommand called
Apr 18 20:03:29 einstein usb-storage: *** thread awakened.
