Bug 1904

Summary: Inserting OHCI PCMCIA adapter blocks the system, PCI cache line size not supported
Product: Drivers Reporter: Martin Mokrejs (mmokrejs)
Component: USBAssignee: David Brownell (dbrownell)
Status: REJECTED INVALID    
Severity: normal CC: greg
Priority: P2    
Hardware: i386   
OS: Linux   
Kernel Version: 2.6.1-bk4 Subsystem:
Regression: --- Bisected commit-id:
Attachments: dmesg output
lspci -v -v
dmesg caught while removing USB 2.0 device from the PCMCIA card
dmesg output from 2.6.3-rc1 running host
5-in-one reader connected to usb 1.1
5-in-one reader connected to usb 2.0
lsusb -vvv

Description Martin Mokrejs 2004-01-18 05:20:33 UTC
Distribution: Gentoo
Hardware Environment: ASUS L3800C laptop, 1 GB RAM
Software Environment:
Problem Description:

When I plug into the PCMCIA slot my USB 2.0 card with OHCI chipset, system
cannot be used for several dozens of seconds.

Steps to reproduce:
Comment 1 Martin Mokrejs 2004-01-18 05:25:59 UTC
Created attachment 1892 [details]
dmesg output

In teh front of teh file you see internal UHCI controller detected, at then
continuation of the messages received during bootup, then those logged when the
PCMCIA card has been inserted. The card is KOUWELL KW-7004 -
http://www.kouwell.com.tw/555.htm
Comment 2 Martin Mokrejs 2004-01-18 05:26:47 UTC
Created attachment 1893 [details]
lspci -v -v
Comment 3 Martin Mokrejs 2004-01-18 07:15:39 UTC
Created attachment 1894 [details]
dmesg caught while removing USB 2.0 device from the PCMCIA card

It seems to me that only while unloading the PCMCIA card messages are logged.
Otherwise, system is blocked. Therefore, I believe those messages in this file
refer only to the process of unregistering USB 2.0 controller and OHCI
controller.
I'm trying to catch some messages on remote serial console, but no luck to get
logged anything after the system booted to runlevel 3. :(
Comment 4 David Brownell 2004-01-19 15:04:43 UTC
Nothing in either "dmesg" seemed particularly troublesome, and nothing strange 
happens on my system.  You should maybe show what devices are connected 
("cat /proc/bus/usb/devices") when you unplug the Cardbus device. 
 
The only usb-related odd things I saw are: 
 
 - That "unlink after no-IRQ" message.  That's usually a sign that your 
   IRQs aren't set up right (as it says) ... which could easily be the root 
   cause for most those other problems. 
 
 - The "trying reset again" lines on the EHCI root hub.  The hub driver 
   shouldn't have retried for any device that's gone.  Looks innocuous, 
   but maybe not. 
 
 - And the pci_pool_destroy() messages also on those paths.  Possibly 
   due to misbehavior from the hub driver.  These are memory leaks, 
   but unlikely to have any other immediate effect on your system. 
 
The cache line size message is a harmless warning; it means PCI won't 
be as efficient as it might be. 
 
Seems like your problem might be the Firewire OHCI, not anything related 
to USB.  What you should do is plug in the controller and then "rmmod" 
all the drivers it uses ... then "modprobe" them individually, and report 
which one is causing the lockup you describe.   If it's not the ohci-hcd 
or ehci-hcd drivers, then I'll have to close (or transfer) this bug. 
 
Try alt-sysrq-8 to see more of the log messages. 
Comment 5 David Brownell 2004-02-07 05:51:11 UTC
Changing priority from "blocking"; it's been sitting here three weeks with no 
response from the original submitter, clearly it was badly prioritized. 
 
If there's still no info from the submitter in another three weeks (like, does 
it appear in 2.6.2 even after trying "Different ACPI or APIC settings" like 
the message suggests -- "noacpi" and "noapic" at least) I'll feel free to 
reject this for lack of information. 
 
 
Comment 6 Martin Mokrejs 2004-02-08 08:52:56 UTC
Hi,
  I made several attempts now to reproduce, all with 2.6.3-rc1 kernel. I still
get those lockups. I have renamed my /etc/modules.autoload.d/kernel-2.6 file,
but system picks up the one for 2.4 too. Luckily, there were ohci*, uhci* and
ehci* drivers commented out. So, I started with lsmod command which lsited on
radeon module loaded.

  I inserted the PCMCIA card and got on console (singleuser mode):

modprobe: FATAL: Module ohci1394 already in kernel.

modprobe: FATAL: Module ohci1394 already in kernel.

modprobe: FATAL: Module ehci_hcd already in kernel.

modprobe: FATAL: Module ohci1394 already in kernel.

modprobe: FATAL: Module ehci_hcd already in kernel.

modprobe: FATAL: Module ohci_hcd already in kernel.

modprobe: FATAL: Module ehci_hcd already in kernel.

modprobe: FATAL: Module ohci_hcd already in kernel.

modprobe: FATAL: Module uhci_hcd already in kernel.

Disabling IRQ #11
modprobe: FATAL: Module ehci_hcd already in kernel.

modprobe: FATAL: Module ohci_hcd already in kernel.

modprobe: FATAL: Module uhci_hcd already in kernel.

modprobe: FATAL: Module ohci_hcd already in kernel.

modprobe: FATAL: Module uhci_hcd already in kernel.

modprobe: FATAL: Module uhci_hcd already in kernel.

modprobe: FATAL: Module mousedev not found.

--- I unloaded the card and I got my shell prompt again. I attach the dmesg
output, it seems there's something of interrest regarding the IRQ11.



From other trial I can conclude that whenever I try to rmmod ohci1394 which
claims to use ieee1394, I lockup the shell. If I'm in multiuser mode, I can
still open another virtual console and type dmesg, but lsmod block session again.

How can I disable autoloading teh jkernel modules? I use Gentoo linux dist.
Comment 7 Martin Mokrejs 2004-02-08 08:55:51 UTC
Created attachment 2063 [details]
dmesg output from 2.6.3-rc1 running host

I pressed Atl+SysRq+8 when the system was "locked".
Comment 8 Martin Mokrejs 2004-02-08 09:25:13 UTC
I've recompiled kernel without ieee1394 modules. The problem goes away, but I'm
still getting those messages from modprobe except th Disable IRQ #11. It seems
to me kernel attempts several times to insert modules after it recognized card
being newly inserted. On the first trial they succeed but kernel somehow retries
to insmod the modules 3-4times after that.
Comment 9 Martin Mokrejs 2004-02-09 13:59:34 UTC
OK, just "rmmod ohci_hcd" while the pcmcia card is inserted locks the rootshell,
I have to open another window to work.

ehci_hcd 0000:07:00.3: device removed
ehci_hcd 0000:07:00.3: reset command ffffffff park=3 ithresh=63 LReset IAAD
Async Periodic period=?? R
ehci_hcd 0000:07:00.3: HC died; cleaning up  



"Other trials" which I'm unable to desribe/repeat right now gave me:
hub 6-0:1.0: debounce: port 3: delay 100ms stable 4 status 0x501
ehci_hcd 0000:07:00.3: port 3 high speed
ehci_hcd 0000:07:00.3: GetStatus port 3 status 001005 POWER sig=se0  PE CONNECT
hub 6-0:1.0: new USB device on port 3, assigned address 2
usb 6-3: control timeout on ep0out
ehci_hcd 0000:07:00.3: Unlink after no-IRQ?  Different ACPI or APIC settings may
help.
ohci_hcd 0000:07:00.0: device removed!
ohci_hcd 0000:07:00.0: HC died; cleaning up
ohci_hcd 0000:07:00.1: device removed!
ohci_hcd 0000:07:00.1: HC died; cleaning up
ohci_hcd 0000:07:00.2: device removed!
ohci_hcd 0000:07:00.2: HC died; cleaning up
ohci_hcd 0000:07:00.0: remove, state 0
ohci_hcd 0000:07:00.0: roothub graceful disconnect
usb usb1: USB disconnect, address 1
usb usb1: usb_disable_device nuking all URBs
ohci_hcd 0000:07:00.0: shutdown urb f659ee24 pipe 40408180 ep1in-intr
usb usb1: unregistering interface 1-0:1.0
usb usb1: hcd_unlink_urb f659ee24 fail -22
drivers/usb/core/usb.c: usb_hotplug
usb usb1: unregistering device
drivers/usb/core/usb.c: usb_hotplug
ohci_hcd 0000:07:00.0: stop operational controller (state 0x00)
ohci_hcd 0000:07:00.0: OHCI controller state
ohci_hcd 0000:07:00.0: OHCI 3.15, with legacy support registers
ohci_hcd 0000:07:00.0: control 0xffffffff RWE RWC IR HCFS=suspend BLE CLE IE PLE
CBSR=3
ohci_hcd 0000:07:00.0: cmdstatus 0xffffffff SOC=3 OCR BLF CLF HCR
ohci_hcd 0000:07:00.0: intrstatus 0xffffffff MIE OC RHSC FNO UE RD SF WDH SO
ohci_hcd 0000:07:00.0: intrenable 0xffffffff MIE OC RHSC FNO UE RD SF WDH SO
ohci_hcd 0000:07:00.0: ed_periodcurrent ffffffff
ohci_hcd 0000:07:00.0: ed_controlhead ffffffff
ohci_hcd 0000:07:00.0: ed_controlcurrent ffffffff
ohci_hcd 0000:07:00.0: ed_bulkhead ffffffff
Comment 10 Martin Mokrejs 2004-02-09 14:35:23 UTC
Created attachment 2065 [details]
5-in-one reader connected to usb 1.1
Comment 11 Martin Mokrejs 2004-02-09 14:36:06 UTC
Created attachment 2066 [details]
5-in-one reader connected to usb 2.0
Comment 12 Martin Mokrejs 2004-02-09 14:46:10 UTC
Created attachment 2067 [details]
lsusb -vvv
Comment 13 Martin Mokrejs 2004-02-09 14:55:53 UTC
Still withou rebooting the laptop, I removed teh PCMCIA card (usb2.0) with the
reader device attached. When replugged again nothing happened as only uhci_hdc
and ehci_hcd were loaded. So I inserted manually ohci_hcd, and this is what I got:

ohci_hcd: 2003 Oct 13 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
ohci_hcd: block sizes: ed 64 td 64
ohci_hcd 0000:07:00.0: OHCI Host Controller
ohci_hcd 0000:07:00.0: USB HC TakeOver from BIOS/SMM
ohci_hcd 0000:07:00.0: USB HC TakeOver failed!
ohci_hcd 0000:07:00.0: can't reset
drivers/usb/core/hcd-pci.c: init 0000:07:00.0 fail, -1
ohci_hcd: probe of 0000:07:00.0 failed with error -1
ohci_hcd 0000:07:00.1: OHCI Host Controller
ohci_hcd 0000:07:00.1: USB HC TakeOver from BIOS/SMM
ohci_hcd 0000:07:00.1: USB HC TakeOver failed!
ohci_hcd 0000:07:00.1: can't reset
drivers/usb/core/hcd-pci.c: init 0000:07:00.1 fail, -1
ohci_hcd: probe of 0000:07:00.1 failed with error -1
ohci_hcd 0000:07:00.2: OHCI Host Controller
ohci_hcd 0000:07:00.2: USB HC TakeOver from BIOS/SMM
ehci_hcd 0000:07:00.3: device removed
ehci_hcd 0000:07:00.3: reset command ffffffff park=3 ithresh=63 LReset IAAD
Async Periodic period=?? R
ehci_hcd 0000:07:00.3: HC died; cleaning up
ohci_hcd 0000:07:00.2: USB HC TakeOver failed!
ohci_hcd 0000:07:00.2: can't reset
drivers/usb/core/hcd-pci.c: init 0000:07:00.2 fail, -1
ohci_hcd: probe of 0000:07:00.2 failed with error -1

BTW: The PCMCIA card is exactly:
07:00.0 Class ffff: ALi Corporation USB 1.1 Controller (rev ff)
07:00.1 Class ffff: ALi Corporation USB 1.1 Controller (rev ff)
07:00.2 Class ffff: ALi Corporation USB 1.1 Controller (rev ff)
07:00.3 Class ffff: ALi Corporation USB 2.0 Controller (rev ff)
07:00.4 Class ffff: ALi Corporation M5253 P1394 OHCI 1.1 Controller (rev ff)
Comment 14 Martin Mokrejs 2004-02-09 15:56:07 UTC
When I booted again 2.6.3-rc1 with   acpi=off   , no alsa sound drivers, I
managed twice to kill the scsi subsystem used via USB to the card reader (just
reading .jpg files from smartmedia slot in the reader). In both cases, system
somehow blocks - I can switch numlock, I can ctrl+alt+backspace and that's it.
In both cases, I saw logged afterwards:

usb-storage: Timeout -- cancelling URB

and in both cases lsusb resports twice the usb card reader as Genesys Logic
Inc.(after fresh connect I see it only once):

# lsusb 
Bus 005 Device 001: ID 0000:0000  
Bus 004 Device 001: ID 0000:0000  
Bus 003 Device 003: ID 05e3:0760 Genesys Logic, Inc. 
Bus 003 Device 001: ID 0000:0000  
Bus 006 Device 007: ID 05e3:0760 Genesys Logic, Inc. 
Bus 006 Device 001: ID 0000:0000  
Bus 002 Device 001: ID 0000:0000  
Bus 001 Device 002: ID 046d:c00e Logitech, Inc. Optical Mouse
Bus 001 Device 001: ID 0000:0000  
#

In addition, I see it twice in scsi subsystem:

# cat /proc/scsi/scsi 
Attached devices:
Host: scsi0 Channel: 00 Id: 00 Lun: 00
  Vendor: TOSHIBA  Model: DVD-ROM SD-R2212 Rev: 1713
  Type:   CD-ROM                           ANSI SCSI revision: 02
Host: scsi7 Channel: 00 Id: 00 Lun: 00
  Vendor: Generic  Model: STORAGE DEVICE   Rev: 0125
  Type:   Direct-Access                    ANSI SCSI revision: 02
Host: scsi8 Channel: 00 Id: 00 Lun: 00
  Vendor: Generic  Model: STORAGE DEVICE   Rev: 0125
  Type:   Direct-Access                    ANSI SCSI revision: 02
#


Interrestingly, I see the reade only once in usb subsystem:

# cat /proc/bus/usb/devices | grep Read
S:  Product=Flash Reader
#


The first time it happened, I had logged:

Feb  9 23:35:30 vrapenec usb-storage: Timeout -- cancelling URB
Feb  9 23:35:50 vrapenec usb-storage: Timeout -- cancelling URB
Feb  9 23:35:50 vrapenec hub 6-0:1.0: port 2 not reset yet, waiting 10ms
Feb  9 23:35:50 vrapenec hub 6-0:1.0: port 2 not reset yet, waiting 200ms
Feb  9 23:35:50 vrapenec 90
Feb  9 23:35:50 vrapenec 90
Feb  9 23:35:50 vrapenec 90
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 16991
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 16992
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 16993
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 16994
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 16995
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 17086
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 17087
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 17088
<cut>
Feb  9 23:35:50 vrapenec usb-storage: queuecommand called
Feb  9 23:35:50 vrapenec SCSI error : <5 0 0 0> return code = 0x70000
Feb  9 23:35:50 vrapenec SCSI error : <5 0 0 0> return code = 0x70000
Feb  9 23:35:50 vrapenec end_request: I/O error, dev sda, sector 17136
Feb  9 23:35:50 vrapenec end_request: I/O error, dev sda, sector 17136
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 17089
Feb  9 23:35:50 vrapenec Buffer I/O error on device sda1, logical block 17090
<cut>
ohci_hcd 0000:07:00.0: GetStatus roothub.portstatus [2] = 0x00010101 CSC P
PS CCS
Feb  9 23:35:50 vrapenec hub 3-0:1.0: port 2, status 101, change 1, 12 Mb/s
Feb  9 23:35:50 vrapenec ohci_hcd 0000:07:00.0: GetStatus roothub.portstatus [2]
= 0x00100103 PRSC PPS PES CCS
Feb  9 23:35:50 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 2
Feb  9 23:35:50 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 2
Feb  9 23:35:50 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 2
Feb  9 23:35:50 vrapenec drivers/usb/core/message.c: USB device number 2 default
language ID 0x409
Feb  9 23:35:50 vrapenec usb 3-2: SerialNumber: 03457
Feb  9 23:35:50 vrapenec usb 3-2: SerialNumber: 03457
Feb  9 23:35:50 vrapenec usb 3-2: SerialNumber: 03457
Feb  9 23:35:50 vrapenec drivers/usb/core/usb.c: usb_hotplug
Feb  9 23:35:51 vrapenec usb-storage: Transport: Bulk
Feb  9 23:35:51 vrapenec usb-storage: Protocol: Transparent SCSI
Feb  9 23:35:51 vrapenec usb-storage: Endpoints: In: 0xf63c51e8 Out: 0xf63c51fc
Int: 0x00000000 (Period 0)
Feb  9 23:35:51 vrapenec usb-storage: usb_stor_control_msg: rq=fe rqtype=a1
value=0000 index=00 len=1
Feb  9 23:35:51 vrapenec usb-storage: *** thread awakened.
Feb  9 23:35:51 vrapenec usb-storage: Command INQUIRY (6 bytes)
Feb  9 23:35:51 vrapenec usb-storage:  12 00 00 00 24 00
Feb  9 23:35:51 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x1a7 L 36 F
128 Trg 0 LUN 0 CL 6
Feb  9 23:35:51 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb  9 23:35:51 vrapenec usb-storage: -- transfer complete
Feb  9 23:35:51 vrapenec usb-storage: Status code 0; transferred 36/36
Feb  9 23:35:51 vrapenec usb-storage: Status code 0; transferred 13/13
Feb  9 23:35:51 vrapenec usb-storage: queuecommand called
Feb  9 23:35:51 vrapenec usb-storage: Status code 0; transferred 31/31
Feb  9 23:35:51 vrapenec usb-storage: Status code 0; transferred 40/40
Feb  9 23:35:51 vrapenec usb-storage: -- transfer complete
Feb  9 23:35:51 vrapenec usb-storage: Bulk data transfer result 0x0
Feb  9 23:35:51 vrapenec usb-storage: Attempting to get CSW...
Feb  9 23:35:51 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb  9 23:35:51 vrapenec Vendor: Generic   Model: STORAGE DEVICE    Rev: 0125
Feb  9 23:35:51 vrapenec Type:   Direct-Access                      ANSI SCSI
revision: 02
<cut>
Feb  9 23:35:51 vrapenec Attached scsi removable disk sdb at scsi6, channel 0,
id 0, lun 0


From the first case when it happened I conclude, that usb re-detects the card
reader again, because I had lost /dev/sda1 but /dev/sdb1 appeared, I could mount
it and read. Something similar happened now again:

lr-xr-xr-x    1 root     root           33 Feb  9 23:49 /dev/sda ->
scsi/host7/bus0/target0/lun0/disc
lr-xr-xr-x    1 root     root           34 Feb  9 23:49 /dev/sda1 ->
scsi/host7/bus0/target0/lun0/part1
lr-xr-xr-x    1 root     root           33 Feb  9 23:53 /dev/sdb ->
scsi/host8/bus0/target0/lun0/disc
lr-xr-xr-x    1 root     root           34 Feb  9 23:53 /dev/sdb1 ->
scsi/host8/bus0/target0/lun0/part1




Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39263
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39264
Feb  9 23:53:34 vrapenec scsi7 (0:0): rejecting I/O to offline device
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 113
Feb  9 23:53:34 vrapenec lost page write due to I/O error on sda1
Feb  9 23:53:34 vrapenec lost page write due to I/O error on sda1
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 114
Feb  9 23:53:34 vrapenec lost page write due to I/O error on sda1
Feb  9 23:53:34 vrapenec lost page write due to I/O error on sda1
Feb  9 23:53:34 vrapenec scsi7 (0:0): rejecting I/O to offline device
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39009
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39010
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39011
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39012
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39013
Feb  9 23:53:34 vrapenec Buffer I/O error on device sda1, logical block 39014
Feb  9 23:53:35 vrapenec Buffe<7>ohci_hcd 0000:07:00.0: GetStatus
roothub.portstatus [2] = 0x00010101 CSC PPS CCS
Feb  9 23:53:35 vrapenec hub 3-0:1.0: port 2, status 101, change 1, 12 Mb/s
Feb  9 23:53:35 vrapenec ohci_hcd 0000:07:00.0: GetStatus roothub.portstatus [2]
= 0x00100103 PRSC PPS PES CCS
Feb  9 23:53:35 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 3
Feb  9 23:53:35 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 3
Feb  9 23:53:35 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 3
Feb  9 23:53:35 vrapenec drivers/usb/core/message.c: USB device number 3 default
language ID 0x409
Feb  9 23:53:35 vrapenec usb 3-2: SerialNumber: 03457
Feb  9 23:53:35 vrapenec usb 3-2: SerialNumber: 03457
Feb  9 23:53:35 vrapenec usb 3-2: SerialNumber: 03457
Feb  9 23:53:35 vrapenec drivers/usb/core/usb.c: usb_hotplug
Feb  9 23:53:35 vrapenec usb-storage: Transport: Bulk
Feb  9 23:53:35 vrapenec usb-storage: Protocol: Transparent SCSI
<cut>
Feb  9 23:53:35 vrapenec Vendor: Generic   Model: STORAGE DEVICE    Rev: 0125
Feb  9 23:53:35 vrapenec Type:   Direct-Access                      ANSI SCSI
revision: 02
<cut>
Feb  9 23:53:35 vrapenec /dev/scsi/host8/bus0/target0/lun0:<7>usb-storage:
queuecommand called
<cut>
Feb  9 23:53:36 vrapenec Attached scsi removable disk sdb at scsi8, channel 0,
id 0, lun 0
Feb  9 23:53:36 vrapenec Attached scsi generic sg2 at scsi8, channel 0, id 0,
lun 0,  type 0
<cut>
Feb  9 23:53:36 vrapenec usb-storage: queuecommand called
Feb  9 23:53:36 vrapenec usb-storage: queuecommand called
Feb  9 23:53:36 vrapenec usb-storage: *** thread awakened.
Feb  9 23:53:36 vrapenec usb-storage: Bad target number (7:0)
Feb  9 23:53:36 vrapenec usb-storage: scsi cmd done, result=0x40000
Feb  9 23:53:36 vrapenec usb-storage: *** thread sleeping.
Feb  9 23:54:03 vrapenec buffer layer error at fs/buffer.c:1820
Feb  9 23:54:03 vrapenec buffer layer error at fs/buffer.c:1820
Feb  9 23:54:03 vrapenec Call Trace:
Feb  9 23:54:03 vrapenec Call Trace:
Feb  9 23:54:03 vrapenec [<c0158d4f>] __block_write_full_page+0x1f5/0x3c6
Feb  9 23:54:03 vrapenec [<c0158d4f>] __block_write_full_page+0x1f5/0x3c6
Feb  9 23:54:03 vrapenec [<c015a4e3>] block_write_full_page+0xe4/0xf0
Feb  9 23:54:03 vrapenec [<c015a4e3>] block_write_full_page+0xe4/0xf0
Feb  9 23:54:03 vrapenec [<c015cef5>] blkdev_get_block+0x0/0x4d
Feb  9 23:54:03 vrapenec [<c015cef5>] blkdev_get_block+0x0/0x4d
Feb  9 23:54:03 vrapenec [<c015d03e>] blkdev_writepage+0x1f/0x23
Feb  9 23:54:03 vrapenec [<c015d03e>] blkdev_writepage+0x1f/0x23
Feb  9 23:54:03 vrapenec [<c015cef5>] blkdev_get_block+0x0/0x4d
Feb  9 23:54:03 vrapenec [<c015cef5>] blkdev_get_block+0x0/0x4d
Feb  9 23:54:03 vrapenec [<c0175dcf>] mpage_writepages+0x1ff/0x2d0
Feb  9 23:54:03 vrapenec [<c0175dcf>] mpage_writepages+0x1ff/0x2d0
Feb  9 23:54:03 vrapenec [<c015d01f>] blkdev_writepage+0x0/0x23
Feb  9 23:54:03 vrapenec [<c015d01f>] blkdev_writepage+0x0/0x23
Feb  9 23:54:03 vrapenec [<c015e19e>] generic_writepages+0x1f/0x23
Feb  9 23:54:03 vrapenec [<c015e19e>] generic_writepages+0x1f/0x23
Feb  9 23:54:03 vrapenec [<c013ec7e>] do_writepages+0x1e/0x38
Feb  9 23:54:03 vrapenec [<c013ec7e>] do_writepages+0x1e/0x38
Feb  9 23:54:03 vrapenec [<c01745b0>] __sync_single_inode+0xd7/0x22f
Feb  9 23:54:03 vrapenec [<c01745b0>] __sync_single_inode+0xd7/0x22f
Feb  9 23:54:03 vrapenec [<c0174956>] sync_sb_inodes+0x1a0/0x25a
Feb  9 23:54:03 vrapenec [<c0174956>] sync_sb_inodes+0x1a0/0x25a
Feb  9 23:54:03 vrapenec [<c0174a60>] writeback_inodes+0x50/0xa3
Feb  9 23:54:03 vrapenec [<c0174a60>] writeback_inodes+0x50/0xa3
Feb  9 23:54:03 vrapenec [<c013eb08>] wb_kupdate+0x9c/0x114
Feb  9 23:54:03 vrapenec [<c013eb08>] wb_kupdate+0x9c/0x114
Feb  9 23:54:03 vrapenec [<c013f047>] __pdflush+0xd7/0x1d0
Feb  9 23:54:03 vrapenec [<c013f047>] __pdflush+0xd7/0x1d0
Feb  9 23:54:03 vrapenec [<c013f140>] pdflush+0x0/0x13
Feb  9 23:54:03 vrapenec [<c013f140>] pdflush+0x0/0x13
Feb  9 23:54:03 vrapenec [<c013f14f>] pdflush+0xf/0x13
Feb  9 23:54:03 vrapenec [<c013f14f>] pdflush+0xf/0x13
Feb  9 23:54:03 vrapenec [<c013ea6c>] wb_kupdate+0x0/0x114
Feb  9 23:54:03 vrapenec [<c013ea6c>] wb_kupdate+0x0/0x114
Feb  9 23:54:03 vrapenec [<c0107250>] kernel_thread_helper+0x0/0xb
Feb  9 23:54:03 vrapenec [<c0107250>] kernel_thread_helper+0x0/0xb
Feb  9 23:54:03 vrapenec [<c0107255>] kernel_thread_helper+0x5/0xb
Feb  9 23:54:03 vrapenec [<c0107255>] kernel_thread_helper+0x5/0xb
Feb  9 23:54:03 vrapenec 
Feb  9 23:54:03 vrapenec 
Feb  9 23:54:03 vrapenec buffer layer error at fs/buffer.c:2666
Feb  9 23:54:03 vrapenec buffer layer error at fs/buffer.c:2666
Feb  9 23:54:03 vrapenec Call Trace:
Feb  9 23:54:03 vrapenec Call Trace:
Feb  9 23:54:03 vrapenec [<c015a687>] submit_bh+0x11a/0x169
Feb  9 23:54:03 vrapenec [<c015a687>] submit_bh+0x11a/0x169
Feb  9 23:54:03 vrapenec [<c0158d27>] __block_write_full_page+0x1cd/0x3c6
Feb  9 23:54:03 vrapenec [<c0158d27>] __block_write_full_page+0x1cd/0x3c6
Feb  9 23:54:03 vrapenec [<c015a4e3>] block_write_full_page+0xe4/0xf0
Feb  9 23:54:03 vrapenec [<c015a4e3>] block_write_full_page+0xe4/0xf0
Feb  9 23:54:03 vrapenec [<c015cef5>] blkdev_get_block+0x0/0x4d
Feb  9 23:54:03 vrapenec [<c015cef5>] blkdev_get_block+0x0/0x4d
Feb  9 23:54:03 vrapenec [<c015d03e>] blkdev_writepage+0x1f/0x23
Feb  9 23:54:03 vrapenec [<c015d03e>] blkdev_writepage+0x1f/0x23
Feb  9 23:54:03 vrapenec [<c015cef5>] <3>scsi7 (0:0): rejecting I/O to offline
device
Feb  9 23:54:03 vrapenec [<c015cef5>] <3>scsi7 (0:0): rejecting I/O to offline
device
Feb  9 23:54:03 vrapenec Buffer I/O error on device sda1, logical block 114
Feb  9 23:54:03 vrapenec lost page write due to I/O error on sda1
Feb  9 23:54:03 vrapenec lost page write due to I/O error on sda1
Feb  9 23:59:23 vrapenec scsi7 (0:0): rejecting I/O to offline device
Feb  9 23:59:23 vrapenec FAT: bread(block 6) in fat_access failed
Feb 10 00:00:01 vrapenec scsi7 (0:0): rejecting I/O to offline device
Feb 10 00:00:01 vrapenec FAT: Directory bread(block 113) failed
Feb 10 00:00:01 vrapenec scsi7 (0:0): rejecting I/O to offline device
Feb 10 00:00:01 vrapenec FAT: Directory bread(block 114) failed



The buffer IO error messages I saw also in the first crash. The kernel crash I
see now for the first time in this subsystem.

Comment 15 Martin Mokrejs 2004-02-09 16:49:55 UTC
For the third time same usb/scsi bug, this time I did not kill my X but rather
removed the reader device from usb port:

Feb 10 00:56:52 vrapenec usb-storage: -- transfer complete
Feb 10 00:56:52 vrapenec usb-storage: Bulk data transfer result 0x0
Feb 10 00:56:52 vrapenec usb-storage: Attempting to get CSW...
Feb 10 00:56:52 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 00:56:52 vrapenec usb-storage: queuecommand called
Feb 10 00:57:22 vrapenec usb-storage: command_abort called
Feb 10 00:57:22 vrapenec usb-storage: usb_stor_stop_transport called
Feb 10 00:57:22 vrapenec usb-storage: -- cancelling URB
Feb 10 00:57:23 vrapenec ehci_hcd 0000:07:00.3: devpath 2 ep0out 3strikes
Feb 10 00:57:23 vrapenec usb-storage: Soft reset failed: -71
Feb 10 00:57:23 vrapenec usb-storage: scsi command aborted
Feb 10 00:57:23 vrapenec usb-storage: *** thread sleeping.
Feb 10 00:57:23 vrapenec usb-storage: queuecommand called
Feb 10 00:57:23 vrapenec usb-storage: *** thread awakened.
Feb 10 00:57:23 vrapenec usb-storage: Command TEST_UNIT_READY (6 bytes)
Feb 10 00:57:23 vrapenec usb-storage:  00 00 00 00 00 00
Feb 10 00:57:23 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x126 L 0 F 0
Trg 0 LUN 0 CL 6
Feb 10 00:57:23 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 00:57:23 vrapenec ehci_hcd 0000:07:00.3: devpath 2 ep0out 3strikes
Feb 10 00:57:23 vrapenec usb-storage: Soft reset failed: -71
Feb 10 00:57:23 vrapenec usb-storage: scsi cmd done, result=0x70000
Feb 10 00:57:23 vrapenec usb-storage: *** thread sleeping.
Feb 10 00:57:23 vrapenec usb-storage: device_reset called
Feb 10 00:57:23 vrapenec usb-storage: usb_stor_Bulk_reset called
Feb 10 00:57:23 vrapenec usb-storage: usb_stor_control_msg: rq=ff rqtype=21
value=0000 index=00 len=0
Feb 10 00:57:23 vrapenec usb-storage: usb_reset_device returns -19
Feb 10 00:57:23 vrapenec scsi: Device offlined - not ready after error recovery:
host 1 channel 0 id 0 lun 0
Feb 10 00:57:23 vrapenec scsi: Device offlined - not ready after error recovery:
host 1 channel 0 id 0 lun 0
Feb 10 00:57:23 vrapenec scsi: Device offlined - not ready after error recovery:
host 1 channel 0 id 0 lun 0
Feb 10 00:57:23 vrapenec SCSI error : <1 0 0 0> return code = 0x70000
Feb 10 00:57:23 vrapenec SCSI error : <1 0 0 0> return code = 0x70000
Feb 10 00:57:23 vrapenec end_request: I/O error, dev sda, sector 20008
Feb 10 00:57:23 vrapenec end_request: I/O error, dev sda, sector 20008
Feb 10 00:57:23 vrapenec Buffer I/O error on device sda1, logical block 19961
Feb 10 00:57:23 vrapenec Buffer I/O error on device sda1, logical block 19962

As long as the reader device was unplugged, the was only /dev/sda1. Replugging
it caused /dev/sda1 to disappear and /dev/sdb1 gets detected, looks sane. So
only killing X session in previous 2 cases causes somehow that /dev/sda1 stays
and /dev/sdb1 appears.

The trick might be that while re-plugging the reader, *ehci_hcd* is used and
which corretly unregisters the old instance(instead of ohci_hcd):

ehci_hcd 0000:07:00.3: GetStatus port 2 status 001803
 POWER sig=j  CSC CONNECT
Feb 10 01:01:03 vrapenec hub 6-0:1.0: port 2, status 501, change 1, 480 Mb/s
Feb 10 01:01:03 vrapenec usb 6-2: USB disconnect, address 2
Feb 10 01:01:03 vrapenec usb 6-2: USB disconnect, address 2
Feb 10 01:01:03 vrapenec usb 6-2: USB disconnect, address 2
Feb 10 01:01:03 vrapenec usb 6-2: usb_disable_device nuking all URBs
Feb 10 01:01:03 vrapenec usb 6-2: unregistering interface 6-2:1.0
Feb 10 01:01:03 vrapenec usb-storage: storage_disconnect() called
Feb 10 01:01:03 vrapenec usb-storage: usb_stor_stop_transport called
Feb 10 01:01:03 vrapenec usb-storage: -- dissociate_dev
Feb 10 01:01:04 vrapenec usb-storage: Transport: Bulk
Feb 10 01:01:04 vrapenec usb-storage: Protocol: Transparent SCSI
<cut>
Feb 10 01:01:04 vrapenec Attached scsi removable disk sdb at scsi2, channel 0,
id 0, lun 0
Feb 10 01:01:04 vrapenec Attached scsi generic sg1 at scsi2, channel 0, id 0,
lun 0,  type 0

Comment 16 David Brownell 2004-02-09 17:11:05 UTC
All these updates, and still I don't see results for the two    
specific experiments requested...    
    
Whenever you see those messages like "Unlink after no-IRQ?",    
that means there's a non-USB bug.  Before it makes ANY sense    
whatever to report USB issues, you need to resolve those.  That's  
the point of the two specific experiments requested!!! 
    
There's a patch that I expect to see in 2.6.3-rc2, making minor    
changes in USB IRQ handling.  That might affect some of these    
problems.  Or might not.   (It's already in Linus' BK...) 
 
The usb_reset_device() failure is maybe odd, but that code is 
known to be buggy.  As is some of the GeneSys hardware. 
 
And for that matter, could be that Firewire+USB adapter is 
giving PCI indigestion.  If it's the one I think it is, nobody has 
managed to get it to deliver IRQs yet. 
 
 
 
Comment 17 Martin Mokrejs 2004-02-09 17:16:25 UTC
Yes, having in memory only ehci_hcd and uhci_hcd while accessing the SM media in
the reader device causes block of the system for a minute, system logged Buffer
I/O error but after a while system works again.

The mountpoint where the scsi device was mounted has to be unplugged and
replugged again. Unloading/reloading usb_storage doesn't force scsi subsystem to
redetect the scsi device on it(/proc/scsi/scsi doesn't show the device).

So somehow ohci_hcd takes sometimes higher preference then ehci_hcd?
Comment 18 David Brownell 2004-02-09 17:23:44 UTC
If you're filing bugs against OHCI, don't use any other HCDs. 
 
Disable them.  I don't want to hear about them again -- you're mixing 
up at least seven different failure modes that I see, which makes it 
far more likely I'll just reject this bug report. 
 
 
Comment 19 Martin Mokrejs 2004-02-09 17:29:47 UTC
But without the ieee1394 and ohci1394 stuff I don't get the DISABLED IRQ error.

With acpi=off (in addition to firewire and sound modules removed) I still get
scsi broken on top os usb while "Unlink after no-IRQ?" is gone!

Yes, all the time the PCI line is unused/unavailable.

I'll retry the -bk tree, but without acpi I don't have the IRQ issues. So I
thought there's something to fix.
Comment 20 Martin Mokrejs 2004-02-09 18:06:09 UTC
2.6.3-bk2 ... acpi=off (no ohci* no ieee* modules loaded):

Feb 10 02:16:10 vrapenec usb-storage: Bulk data transfer result 0x0
Feb 10 02:16:10 vrapenec usb-storage: Attempting to get CSW...
Feb 10 02:16:10 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 02:16:10 vrapenec usb-storage: queuecommand called
Feb 10 02:16:10 vrapenec usb-storage: Status code 0; transferred 31/31
Feb 10 02:16:10 vrapenec usb-storage: -- transfer complete
Feb 10 02:16:10 vrapenec usb-storage: Bulk command transfer result=0
Feb 10 02:16:10 vrapenec usb-storage: usb_stor_bulk_transfer_sglist: xfer 31744
bytes, 8 entries
Feb 10 02:16:10 vrapenec usb-storage: Status code 0; transferred 13/13
Feb 10 02:16:10 vrapenec usb-storage: -- transfer complete
Feb 10 02:16:10 vrapenec usb-storage: Bulk status result = 0
Feb 10 02:16:10 vrapenec usb-storage: Bulk Status S 0x53425355 T 0x13a R 0 Stat 0x0
Feb 10 02:16:10 vrapenec usb-storage: scsi cmd done, result=0x0
Feb 10 02:16:10 vrapenec usb-storage: *** thread sleeping.
Feb 10 02:16:10 vrapenec usb-storage: *** thread awakened.
Feb 10 02:16:10 vrapenec usb-storage: Command READ_10 (10 bytes)
Feb 10 02:16:10 vrapenec usb-storage:  28 00 00 00 54 c0 00 00 80 00
Feb 10 02:16:10 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x13b L 65536
F 128 Trg 0 LUN 0 CL 10
Feb 10 02:16:10 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 02:16:10 vrapenec usb-storage: Status code 0; transferred 65536/65536
Feb 10 02:16:10 vrapenec usb-storage: -- transfer complete
Feb 10 02:16:10 vrapenec usb-storage: Bulk data transfer result 0x0
Feb 10 02:16:10 vrapenec usb-storage: Attempting to get CSW...
Feb 10 02:16:10 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 02:16:10 vrapenec usb-storage: queuecommand called
Feb 10 02:16:40 vrapenec usb-storage: command_abort called
Feb 10 02:16:40 vrapenec usb-storage: usb_stor_stop_transport called
Feb 10 02:16:40 vrapenec usb-storage: -- cancelling URB
Feb 10 02:17:00 vrapenec usb-storage: Timeout -- cancelling URB
Feb 10 02:17:10 vrapenec usb-storage: command_abort called
Feb 10 02:17:10 vrapenec usb-storage: usb_stor_stop_transport called
Feb 10 02:17:10 vrapenec usb-storage: -- cancelling URB
Feb 10 02:17:30 vrapenec usb-storage: Timeout -- cancelling URB
Feb 10 02:17:50 vrapenec usb-storage: Timeout -- cancelling URB
Feb 10 02:17:50 vrapenec hub 6-0:1.0: port 2 not reset yet, waiting 10ms
Feb 10 02:17:50 vrapenec hub 6-0:1.0: port 2 not reset yet, waiting 200ms
Feb 10 02:17:50 vrapenec 06
Feb 10 02:17:50 vrapenec 06
Feb 10 02:17:50 vrapenec 06
Feb 10 02:17:50 vrapenec Buffer I/O error on device sda1, logical block 21807
Feb 10 02:17:50 vrapenec Buffer I/O error on device sda1, logical block 21808

What should I do now?
Comment 21 Martin Mokrejs 2004-02-09 19:08:16 UTC
To ensure you I have the IRQ problem when acpi=off even on 2.6.3-bk2, here's the
full log:

I connect the PCMCIA card:

PCI: Enabling device 0000:07:00.3 (0000 -> 0002)
ehci_hcd 0000:07:00.3: EHCI Host Controller
ehci_hcd 0000:07:00.3: reset hcs_params 0x103216 dbg=1 cc=3 pcc=2 ordered ports=6
ehci_hcd 0000:07:00.3: reset hcc_params 7002 thresh 0 uframes 256/512/1024
ehci_hcd 0000:07:00.3: capability 0001 at 70
ehci_hcd 0000:07:00.3: irq 11, pci mem fa9e2800
ehci_hcd 0000:07:00.3: new USB bus registered, assigned bus number 3
ehci_hcd 0000:07:00.3: reset command 080002 (park)=0 ithresh=8 period=1024 Reset
HALT
PCI: cache line size of 128 is not supported by device 0000:07:00.3
ehci_hcd 0000:07:00.3: init command 010009 (park)=0 ithresh=1 period=256 RUN
ehci_hcd 0000:07:00.3: USB 2.0 enabled, EHCI 1.00, driver 2003-Dec-29
ehci_hcd 0000:07:00.3: root hub device address 1
usb usb3: new device strings: Mfr=3, Product=2, SerialNumber=1
drivers/usb/core/message.c: USB device number 1 default language ID 0x409
usb usb3: Product: EHCI Host Controller
usb usb3: Manufacturer: Linux 2.6.3-bk2 ehci_hcd
usb usb3: SerialNumber: 0000:07:00.3
drivers/usb/core/usb.c: usb_hotplug
usb usb3: registering 3-0:1.0 (config #1, interface 0)
drivers/usb/core/usb.c: usb_hotplug
hub 3-0:1.0: usb_probe_interface
hub 3-0:1.0: usb_probe_interface - got id
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 6 ports detected
hub 3-0:1.0: standalone hub
hub 3-0:1.0: individual port power switching
hub 3-0:1.0: individual port over-current protection
hub 3-0:1.0: Single TT
hub 3-0:1.0: TT requires at most 8 FS bit times
hub 3-0:1.0: Port indicators are not supported
hub 3-0:1.0: power on to power good time: 20ms
hub 3-0:1.0: hub controller current requirement: 0mA
hub 3-0:1.0: local power source is good
hub 3-0:1.0: no over-current condition exists
hub 3-0:1.0: enabling power on all ports


When I plugin the usb reader, I get:

Feb 10 03:16:05 vrapenec ehci_hcd 0000:07:00.3: GetStatus port 2 status 001803
POWER sig=j  CSC CONNECT
Feb 10 03:16:05 vrapenec hub 3-0:1.0: port 2, status 501, change 1, 480 Mb/s
Feb 10 03:16:05 vrapenec ehci_hcd 0000:07:00.3: port 2 high speed
Feb 10 03:16:05 vrapenec ehci_hcd 0000:07:00.3: GetStatus port 2 status 001005
POWER sig=se0  PE CONNECT
Feb 10 03:16:05 vrapenec hub 3-0:1.0: new USB device on port 2, assigned address 2
Feb 10 03:16:05 vrapenec drivers/usb/core/message.c: USB device number 2 default
language ID 0x409
Feb 10 03:16:05 vrapenec usb 3-2: SerialNumber: 03457
Feb 10 03:16:05 vrapenec drivers/usb/core/usb.c: usb_hotplug
Feb 10 03:16:06 vrapenec Initializing USB Mass Storage driver...
Feb 10 03:16:06 vrapenec usb-storage 3-2:1.0: usb_probe_interface
Feb 10 03:16:06 vrapenec usb-storage 3-2:1.0: usb_probe_interface - got id
Feb 10 03:16:06 vrapenec usb-storage: USB Mass Storage device detected
Feb 10 03:16:06 vrapenec usb-storage: act_altsetting is 0, id_index is 88
Feb 10 03:16:06 vrapenec usb-storage: -- associate_dev
Feb 10 03:16:06 vrapenec usb-storage: GetMaxLUN command result is 1, data is 3
Feb 10 03:16:06 vrapenec scsi1 : SCSI emulation for USB Mass Storage devices
Feb 10 03:16:06 vrapenec usb-storage: queuecommand called
Feb 10 03:16:06 vrapenec usb-storage: Command INQUIRY (6 bytes)
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 36 bytes
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Attempting to get CSW...
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 13/13
Feb 10 03:16:06 vrapenec usb-storage: Bulk status result = 0
Feb 10 03:16:06 vrapenec usb-storage: Fixing INQUIRY data to show SCSI rev 2 - was 0
Feb 10 03:16:06 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:16:06 vrapenec usb-storage: *** thread awakened.
Feb 10 03:16:06 vrapenec usb-storage:  00 00 00<7>usb-storage: Bulk Command S
0x43425355 T 0x10 L 40 F 128 Trg 0 LUN 0 CL 6
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 31/31
Feb 10 03:16:06 vrapenec usb-storage: Bulk command transfer result=0
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 40/40
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk data transfer result 0x0
Feb 10 03:16:06 vrapenec usb-storage: Attempting to get CSW...
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 03:16:06 vrapenec Vendor: Generic   Model: STORAGE DEVICE    Rev: 0125
Feb 10 03:16:06 vrapenec Type:   Direct-Access                      ANSI SCSI
revision: 02
Feb 10 03:16:06 vrapenec usb-storage: queuecommand called
Feb 10 03:16:06 vrapenec usb-storage: *** thread awakened.
Feb 10 03:16:06 vrapenec usb-storage: Command TEST_UNIT_READY (6 bytes)
Feb 10 03:16:06 vrapenec usb-storage:  00 00 00 00 00 00
Feb 10 03:16:06 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x11 L 0 F 0
Trg 0 LUN 0 CL 6
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 13/13
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk status result = 0
Feb 10 03:16:06 vrapenec usb-storage: Bulk Status S 0x53425355 T 0x13 R 0 Stat 0x0
Feb 10 03:16:06 vrapenec usb-storage: scsi cmd done, result=0x0
Feb 10 03:16:06 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:16:06 vrapenec usb-storage: queuecommand called
Feb 10 03:16:06 vrapenec usb-storage: *** thread awakened.
Feb 10 03:16:06 vrapenec usb-storage: Command ALLOW_MEDIUM_REMOVAL (6 bytes)
Feb 10 03:16:06 vrapenec usb-storage:  1e 00 00 00 01 00
Feb 10 03:16:06 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x14 L 0 F 0
Trg 0 LUN 0 CL 6
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 31/31
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk command transfer result=0
Feb 10 03:16:06 vrapenec usb-storage: Attempting to get CSW...
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 13/13
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk status result = 0
Feb 10 03:16:06 vrapenec usb-storage: Bulk Status S 0x53425355 T 0x14 R 0 Stat 0x0
Feb 10 03:16:06 vrapenec usb-storage: scsi cmd done, result=0x0
Feb 10 03:16:06 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:16:06 vrapenec /dev/scsi/host1/bus0/target0/lun0:<7>usb-storage:
queuecommand called
Feb 10 03:16:06 vrapenec usb-storage: *** thread awakened.
Feb 10 03:16:06 vrapenec usb-storage: Command READ_10 (10 bytes)
Feb 10 03:16:06 vrapenec usb-storage:  28 00 00 00 00 00 00 00 08 00
Feb 10 03:16:06 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x15 L 4096 F
128 Trg 0 LUN 0 CL 10
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 31/31
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk command transfer result=0
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_sglist: xfer 4096
bytes, 1 entries
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 4096/4096
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk data transfer result 0x0
Feb 10 03:16:06 vrapenec usb-storage: Attempting to get CSW...
Feb 10 03:16:06 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes
Feb 10 03:16:06 vrapenec usb-storage: Status code 0; transferred 13/13
Feb 10 03:16:06 vrapenec usb-storage: -- transfer complete
Feb 10 03:16:06 vrapenec usb-storage: Bulk status resu<7>usb-storage:
queuecommand called
Feb 10 03:16:06 vrapenec usb-storage: *** thread awakened.
Feb 10 03:16:06 vrapenec usb-storage: Bad target number (5:0)
Feb 10 03:16:06 vrapenec usb-storage: scsi cmd done, result=0x40000
Feb 10 03:16:06 vrapenec usb-storage: *** thread sleeping.

# cat /proc/interrupts 
           CPU0       
  0:     531558          XT-PIC  timer
  1:       1068          XT-PIC  i8042
  2:          0          XT-PIC  cascade
  5:      28315          XT-PIC  yenta, uhci_hcd
  8:          2          XT-PIC  rtc
  9:        408          XT-PIC  uhci_hcd, eth0
 11:         70          XT-PIC  yenta, ehci_hcd
 12:         86          XT-PIC  i8042
 14:       5626          XT-PIC  ide0
 15:         37          XT-PIC  ide1
NMI:          0 
LOC:          0 
ERR:          0
#


And when accessing the media, I get:

Feb 10 03:19:35 vrapenec usb-storage: usb_stor_bulk_transfer_sglist: xfer 65536
bytes, 16 entries
Feb 10 03:19:35 vrapenec usb-storage: Status code 0; transferred 13/13
Feb 10 03:19:35 vrapenec usb-storage: -- transfer complete
Feb 10 03:19:35 vrapenec usb-storage: Bulk status result = 0
Feb 10 03:19:35 vrapenec usb-storage: Bulk Status S 0x53425355 T 0x19d R 0 Stat 0x0
Feb 10 03:19:35 vrapenec usb-storage: scsi cmd done, result=0x0
Feb 10 03:19:35 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:19:35 vrapenec usb-storage: *** thread awakened.
Feb 10 03:19:35 vrapenec usb-storage: Command READ_10 (10 bytes)
Feb 10 03:19:35 vrapenec usb-storage:  28 00 00 00 82 50 00 00 80 00
Feb 10 03:19:35 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x19e L 65536
F 128 Trg 0 LUN 0 CL 10
Feb 10 03:19:35 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:20:05 vrapenec usb-storage: Status code -104; transferred 0/31
Feb 10 03:20:05 vrapenec usb-storage: -- transfer cancelled
Feb 10 03:20:05 vrapenec usb-storage: Bulk command transfer result=4
Feb 10 03:20:05 vrapenec usb-storage: -- command was aborted
Feb 10 03:20:05 vrapenec usb-storage: usb_stor_Bulk_reset called
Feb 10 03:20:05 vrapenec usb-storage: usb_stor_control_msg: rq=ff rqtype=21
value=0000 index=00 len=0
Feb 10 03:20:25 vrapenec usb-storage: Soft reset failed: -104
Feb 10 03:20:25 vrapenec usb-storage: scsi command aborted
Feb 10 03:20:25 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:20:25 vrapenec usb-storage: queuecommand called
Feb 10 03:20:25 vrapenec usb-storage: *** thread awakened.
Feb 10 03:20:25 vrapenec usb-storage: Command TEST_UNIT_READY (6 bytes)
Feb 10 03:20:25 vrapenec usb-storage:  00 00 00 00 00 00
Feb 10 03:20:25 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x19e L 0 F 0
Trg 0 LUN 0 CL 6
Feb 10 03:20:25 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:20:35 vrapenec usb-storage: Status code -104; transferred 0/31
Feb 10 03:20:35 vrapenec usb-storage: -- transfer cancelled
Feb 10 03:20:35 vrapenec usb-storage: Bulk command transfer result=4
Feb 10 03:20:35 vrapenec usb-storage: -- command was aborted
Feb 10 03:20:35 vrapenec usb-storage: usb_stor_Bulk_reset called
Feb 10 03:20:35 vrapenec usb-storage: usb_stor_control_msg: rq=ff rqtype=21
value=0000 index=00 len=0
Feb 10 03:20:55 vrapenec usb-storage: Soft reset failed: -104
Feb 10 03:20:55 vrapenec usb-storage: scsi command aborted
Feb 10 03:20:55 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:20:55 vrapenec usb-storage: device_reset called
Feb 10 03:20:55 vrapenec usb-storage: usb_stor_Bulk_reset called
Feb 10 03:20:55 vrapenec usb-storage: usb_stor_control_msg: rq=ff rqtype=21
value=0000 index=00 len=0
Feb 10 03:21:15 vrapenec usb-storage: Soft reset failed: -104
Feb 10 03:21:15 vrapenec usb-storage: bus_reset called
Feb 10 03:21:15 vrapenec hub 3-0:1.0: port 2 not reset yet, waiting 10ms
Feb 10 03:21:15 vrapenec ehci_hcd 0000:07:00.3: port 2 full speed --> companion
Feb 10 03:21:15 vrapenec ehci_hcd 0000:07:00.3: GetStatus port 2 status 003801
POWER OWNER sig=j  CONNECT
Feb 10 03:21:15 vrapenec usb-storage: usb_reset_device returns -19
Feb 10 03:21:15 vrapenec scsi: Device offlined - not ready after error recovery:
host 1 channel 0 id 0 lun 0
Feb 10 03:21:15 vrapenec scsi: Device offlined - not ready after error recovery:
host 1 channel 0 id 0 lun 0
Feb 10 03:21:15 vrapenec scsi: Device offlined - not ready after error recovery:
host 1 channel 0 id 0 lun 0
Feb 10 03:21:15 vrapenec SCSI error : <1 0 0 0> return code = 0x50000
Feb 10 03:21:15 vrapenec SCSI error : <1 0 0 0> return code = 0x50000
Feb 10 03:21:15 vrapenec end_request: I/O error, dev sda, sector 33360
Feb 10 03:21:15 vrapenec end_request: I/O error, dev sda, sector 33360
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33313
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33314
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33315
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33316
<cut>
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33412
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33413
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33414
Feb 10 03:21:15 vrapenec Buffe<7>usb-storage: *** thread awakened.
Feb 10 03:21:15 vrapenec usb-storage: Command READ_10 (10 bytes)
Feb 10 03:21:15 vrapenec usb-storage:  28 00 00 00 82 d0 00 00 80 00
Feb 10 03:21:15 vrapenec usb-storage: Bulk Command S 0x43425355 T 0x19f L 65536
F 128 Trg 0 LUN 0 CL 10
Feb 10 03:21:15 vrapenec usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
Feb 10 03:21:15 vrapenec usb-storage: Status code -19; transferred 0/31
Feb 10 03:21:15 vrapenec usb-storage: -- unknown error
Feb 10 03:21:15 vrapenec usb-storage: Bulk command transfer result=4
Feb 10 03:21:15 vrapenec usb-storage: -- transport indicates error, resetting
Feb 10 03:21:15 vrapenec usb-storage: usb_stor_Bulk_reset called
Feb 10 03:21:15 vrapenec usb-storage: usb_stor_control_msg: rq=ff rqtype=21
value=0000 index=00 len=0
Feb 10 03:21:15 vrapenec usb-storage: Soft reset failed: -19
Feb 10 03:21:15 vrapenec usb-storage: scsi cmd done, result=0x70000
Feb 10 03:21:15 vrapenec usb-storage: *** thread sleeping.
Feb 10 03:21:15 vrapenec ck 33475
Feb 10 03:21:15 vrapenec ck 33475
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33476
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33477
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33478
<cut>
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33567
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33568
Feb 10 03:21:15 vrapenec scsi1 (0:0): rejecting I/O to offline device
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 113
Feb 10 03:21:15 vrapenec lost page write due to I/O error on sda1
Feb 10 03:21:15 vrapenec lost page write due to I/O error on sda1
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 114
Feb 10 03:21:15 vrapenec lost page write due to I/O error on sda1
Feb 10 03:21:15 vrapenec lost page write due to I/O error on sda1
Feb 10 03:21:15 vrapenec scsi1 (0:0): rejecting I/O to offline device
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33313
Feb 10 03:21:15 vrapenec Buffer I/O error on device sda1, logical block 33314
Comment 22 Martin Mokrejs 2004-02-10 03:31:29 UTC
Could one of these pacthes help? They don't apply to 2.6.3-bk2, but it seems
they helped on 2.6.2 kernel.

http://www.ussg.iu.edu/hypermail/linux/kernel/0402.1/0041.html
Comment 23 Martin Mokrejs 2004-02-29 13:48:44 UTC
I have still problems on 2.6.4-rc1 (no OHCI nor IEEE1394 in kernel):

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 0x20 R 0 Stat 0x0
usb-storage: scsi cmd done, result=0x0
usb-storage: *** thread sleeping.
usb-storage: queuecommand called
usb-storage: *** thread awakened.
usb-storage: Command READ_10 (10 bytes)
usb-storage:  28 00 00 00 00 af 00 00 80 00
usb-storage: Bulk Command S 0x43425355 T 0x21 L 65536 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_sglist: xfer 65536 bytes, 16 entries
ehci_hcd 0000:07:00.3: devpath 3 ep1in 3strikes
usb-storage: Status code -71; transferred 16384/65536
usb-storage: -- unknown error
usb-storage: Bulk data transfer result 0x4
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
ehci_hcd 0000:07:00.3: devpath 3 ep0out 3strikes
usb-storage: Soft reset failed: -71
usb-storage: scsi cmd done, result=0x70000
usb-storage: *** thread sleeping.
usb-storage: queuecommand called
usb-storage: *** thread awakened.
usb-storage: Command READ_10 (10 bytes)
usb-storage:  28 00 00 00 00 af 00 00 80 00
usb-storage: Bulk Command S 0x43425355 T 0x22 L 65536 F 128 Trg 0 LUN 0 CL 10
usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
ehci_hcd 0000:07:00.3: devpath 3 ep2out 3strikes
usb-storage: Status code -71; transferred 0/31
usb-storage: -- unknown error
usb-storage: Bulk command transfer result=4
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
ehci_hcd 0000:07:00.3: devpath 3 ep0out 3strikes
usb-storage: Soft reset failed: -71
usb-storage: scsi cmd done, result=0x70000
usb-storage: *** thread sleeping.
usb-storage: queuecommand called
usb-storage: *** thread awakened.
usb-storage: Command READ_10 (10 bytes)
usb-storage:  28 00 00 00 00 af 00 00 80 00
usb-storage: Bulk Command S 0x43425355 T 0x23 L 65536 F 128 Trg 0 LUN 0 CL 10
usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
ehci_hcd 0000:07:00.3: devpath 3 ep2out 3strikes
usb-storage: Status code -71; transferred 0/31
usb-storage: -- unknown error
usb-storage: Bulk command transfer result=4
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
ehci_hcd 0000:07:00.3: devpath 3 ep0out 3strikes
usb-storage: Soft reset failed: -71
usb-storage: scsi cmd done, result=0x70000
usb-storage: *** thread sleeping.
usb-storage: queuecommand called
usb-storage: *** thread awakened.
usb-storage: Command READ_10 (10 bytes)
usb-storage:  28 00 00 00 00 af 00 00 80 00
usb-storage: Bulk Command S 0x43425355 T 0x24 L 65536 F 128 Trg 0 LUN 0 CL 10
usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
ehci_hcd 0000:07:00.3: devpath 3 ep2out 3strikes
usb-storage: Status code -71; transferred 0/31
usb-storage: -- unknown error
usb-storage: Bulk command transfer result=4
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
ehci_hcd 0000:07:00.3: devpath 3 ep0out 3strikes
usb-storage: Soft reset failed: -71
usb-storage: scsi cmd done, result=0x70000
usb-storage: *** thread sleeping.
usb-storage: queuecommand called
usb-storage: *** thread awakened.
usb-storage: Command READ_10 (10 bytes)
usb-storage:  28 00 00 00 00 af 00 00 80 00
usb-storage: Bulk Command S 0x43425355 T 0x25 L 65536 F 128 Trg 0 LUN 0 CL 10
usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
ehci_hcd 0000:07:00.3: devpath 3 ep2out 3strikes
usb-storage: Status code -71; transferred 0/31
usb-storage: -- unknown error
usb-storage: Bulk command transfer result=4
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
ehci_hcd 0000:07:00.3: devpath 3 ep0out 3strikes
usb-storage: Soft reset failed: -71
usb-storage: scsi cmd done, result=0x70000
usb-storage: *** thread sleeping.
SCSI error : <1 0 0 0> return code = 0x70000
end_request: I/O error, dev sda, sector 175
Buffer I/O error on device sda1, logical block 128
usb-storage: queuecommand called
usb-storage: *** thread awakened.

# lsusb
Bus 003 Device 002: ID 05e3:0760 Genesys Logic, Inc. 
Bus 003 Device 001: ID 0000:0000  
Bus 002 Device 001: ID 0000:0000  
Bus 001 Device 002: ID 046d:c00e Logitech, Inc. Optical Mouse
Bus 001 Device 001: ID 0000:0000  
#

$ cat /proc/interrupts 
           CPU0       
  0:    1017446          XT-PIC  timer
  1:       2245          XT-PIC  i8042
  2:          0          XT-PIC  cascade
  5:      53485          XT-PIC  yenta, uhci_hcd
  8:          2          XT-PIC  rtc
  9:        996          XT-PIC  acpi, uhci_hcd, eth0
 11:        519          XT-PIC  yenta, Intel 82801CA-ICH3, ehci_hcd
 12:         86          XT-PIC  i8042
 14:       7121          XT-PIC  ide0
 15:         37          XT-PIC  ide1
NMI:          0 
LOC:          0 
ERR:          0
MIS:          0
$

#
# USB support
#
CONFIG_USB=y
CONFIG_USB_DEBUG=y

#
# Miscellaneous USB options
#
CONFIG_USB_DEVICEFS=y
CONFIG_USB_BANDWIDTH=y
CONFIG_USB_DYNAMIC_MINORS=y

#
# USB Host Controller Drivers
#
CONFIG_USB_EHCI_HCD=y
# CONFIG_USB_OHCI_HCD is not set
CONFIG_USB_UHCI_HCD=y

#
# USB Device Class drivers
#
# CONFIG_USB_AUDIO is not set
CONFIG_USB_BLUETOOTH_TTY=m
# CONFIG_USB_MIDI is not set
# CONFIG_USB_ACM is not set
CONFIG_USB_PRINTER=m
CONFIG_USB_STORAGE=y
CONFIG_USB_STORAGE_DEBUG=y
# CONFIG_USB_STORAGE_DATAFAB is not set
# CONFIG_USB_STORAGE_FREECOM is not set
# CONFIG_USB_STORAGE_ISD200 is not set
CONFIG_USB_STORAGE_DPCM=y
# CONFIG_USB_STORAGE_HP8200e is not set
# CONFIG_USB_STORAGE_SDDR09 is not set
# CONFIG_USB_STORAGE_SDDR55 is not set
# CONFIG_USB_STORAGE_JUMPSHOT is not set


Comment 24 David Brownell 2004-05-07 07:49:02 UTC
OK, as I said I'd likely do, I'm closing this. 
 
- comment #13 and comment #14 show clear PCMCIA/Cardbus problems, 
  nothing related to OHCI.  PCI config space reading as all-ones, and 
  duplicate devices.  I saw that for a while, seems long fixed.  Not 
  OHCI related. 
 
- Comment #23 shows the problems folk have had with the GeneSys 
  USB adapters. Not OHCI related. 
 
- Since the IRQ problems go away if ACPI is off, clearly you also have 
  non-USB problems.  Not OHCI related. 
 
- In fact, I didn't see even ONE good description of an OHCI issue 
  that would need to be fixed. 
 
In the future, I strongly suggest that you isolate individual bugs in reports. 
I can understand frustration when things don't work, but bugtraq is not 
the right place to dump them ... it's a place to file good descriptions of 
bugs so they can be fixed.