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:
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
Created attachment 1893 [details] lspci -v -v
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. :(
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.
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.
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.
Created attachment 2063 [details] dmesg output from 2.6.3-rc1 running host I pressed Atl+SysRq+8 when the system was "locked".
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.
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
Created attachment 2065 [details] 5-in-one reader connected to usb 1.1
Created attachment 2066 [details] 5-in-one reader connected to usb 2.0
Created attachment 2067 [details] lsusb -vvv
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)
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.
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
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.
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?
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.
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.
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?
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
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
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
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.