Bug 1904
| Summary: | Inserting OHCI PCMCIA adapter blocks the system, PCI cache line size not supported | ||
|---|---|---|---|
| Product: | Drivers | Reporter: | Martin Mokrejs (mmokrejs) |
| Component: | USB | Assignee: | 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
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. |