insert eject sometimes fails and then the whole system hangs

Sebastian Günther sebastian.guenther at qosmotec.com
Wed Mar 1 07:37:04 EST 2006 

We're testing some Sierra Wireless datacards, and have to eject/insert
them rather often.

No always reproduceable we get the following:

Feb  9 21:15:03 dccs75 kernel: PCI: Found 0000:2c:00.0 [1033/0035] 000c03 00
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c01e9580 for 0000:2c:00.0
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c01e9b10 for 0000:2c:00.0
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c027d0b0 for 0000:2c:00.0
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c027d480 for 0000:2c:00.0
Feb  9 21:15:03 dccs75 kernel: PCI: Found 0000:2c:00.1 [1033/0035] 000c03 00
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c01e9580 for 0000:2c:00.1
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c01e9b10 for 0000:2c:00.1
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c027d0b0 for 0000:2c:00.1
Feb  9 21:15:03 dccs75 kernel: PCI: Calling quirk c027d480 for 0000:2c:00.1
Feb  9 21:15:03 dccs75 kernel: got res [f9017000:f9017fff] bus [f9017000:f9017fff] flags 200 for BAR 0 of 0000:2c:00.0
Feb  9 21:15:03 dccs75 kernel: PCI: moved device 0000:2c:00.0 resource 0 (200) to f9017000
Feb  9 21:15:03 dccs75 kernel: got res [f9018000:f9018fff] bus [f9018000:f9018fff] flags 200 for BAR 0 of 0000:2c:00.1
Feb  9 21:15:03 dccs75 kernel: PCI: moved device 0000:2c:00.1 resource 0 (200) to f9018000
Feb  9 21:15:03 dccs75 kernel: PCI: Enabling device 0000:2c:00.0 (0000 -> 0002)
Feb  9 21:15:03 dccs75 kernel: ACPI: PCI Interrupt 0000:2c:00.0[A] -> GSI 56 (level, low) -> IRQ 193
Feb  9 21:15:03 dccs75 kernel: PCI: Enabling bus mastering for device 0000:2c:00.0
Feb  9 21:15:03 dccs75 kernel: PCI: Setting latency timer of device 0000:2c:00.0 to 64
Feb  9 21:15:03 dccs75 kernel: ohci_hcd 0000:2c:00.0: OHCI Host Controller
Feb  9 21:15:03 dccs75 kernel: ohci_hcd 0000:2c:00.0: new USB bus registered, assigned bus number 5
Feb  9 21:15:03 dccs75 kernel: ohci_hcd 0000:2c:00.0: irq 193, io mem 0xf9017000
Feb  9 21:15:03 dccs75 kernel: hub 5-0:1.0: USB hub found
Feb  9 21:15:03 dccs75 kernel: hub 5-0:1.0: 3 ports detected
Feb  9 21:15:03 dccs75 kernel: PCI: Enabling device 0000:2c:00.1 (0000 -> 0002)
Feb  9 21:15:03 dccs75 kernel: ACPI: PCI Interrupt 0000:2c:00.1[B] -> GSI 56 (level, low) -> IRQ 193
Feb  9 21:15:03 dccs75 kernel: PCI: Enabling bus mastering for device 0000:2c:00.1
Feb  9 21:15:03 dccs75 kernel: PCI: Setting latency timer of device 0000:2c:00.1 to 64
Feb  9 21:15:03 dccs75 kernel: ohci_hcd 0000:2c:00.1: OHCI Host Controller
Feb  9 21:15:03 dccs75 kernel: ohci_hcd 0000:2c:00.1: new USB bus registered, assigned bus number 6
Feb  9 21:15:03 dccs75 kernel: ohci_hcd 0000:2c:00.1: irq 193, io mem 0xf9018000
Feb  9 21:15:03 dccs75 kernel: hub 6-0:1.0: USB hub found
Feb  9 21:15:03 dccs75 kernel: hub 6-0:1.0: 2 ports detected
Feb  9 21:15:04 dccs75 pci.agent[22984]:      ohci-hcd: already loaded
Feb  9 21:15:04 dccs75 kernel: usb 5-1: new low speed USB device using ohci_hcd and address 2
Feb  9 21:15:04 dccs75 kernel: usb 5-1: device descriptor read/64, error -110
Feb  9 21:15:04 dccs75 pci.agent[23001]:      ohci-hcd: already loaded
Feb  9 21:15:04 dccs75 kernel: usb 5-1: device descriptor read/64, error -110
Feb  9 21:15:04 dccs75 usb.agent[23041]:      usbcore: already loaded
Feb  9 21:15:04 dccs75 udev[23112]: creating device node '/dev/usbdev5.1'
Feb  9 21:15:04 dccs75 usb.agent[23084]:      usbcore: already loaded
Feb  9 21:15:04 dccs75 udev[23131]: creating device node '/dev/usbdev6.1'
Feb  9 21:15:04 dccs75 kernel: usb 5-1: new low speed USB device using ohci_hcd and address 3
Feb  9 21:15:04 dccs75 kernel: usb 5-1: device descriptor read/64, error -110
Feb  9 21:15:05 dccs75 kernel: usb 5-1: device descriptor read/64, error -110
Feb  9 21:15:08 dccs75 kernel: usb 5-1: new full speed USB device using ohci_hcd and address 5
Feb  9 21:15:08 dccs75 kernel: usbserial_generic 5-1:1.0: Generic converter detected
Feb  9 21:15:08 dccs75 kernel: usb 5-1: Generic converter now attached to ttyUSB4
Feb  9 21:15:08 dccs75 kernel: usbserial_generic 5-1:1.1: Generic converter detected
Feb  9 21:15:08 dccs75 kernel: usb 5-1: Generic converter now attached to ttyUSB5
Feb  9 21:15:14 dccs75 udev[23197]: configured rule in '/etc/udev/rules.d/030qosmotec-dccs.rules[5]' applied, added symlink 'card_not_usable'
Feb  9 21:15:14 dccs75 udev[23197]: creating device node '/dev/ttyUSB5'
Feb  9 21:15:14 dccs75 udev[23204]: creating device node '/dev/usbdev5.5'
Feb  9 21:15:14 dccs75 udev[23203]: configured rule in '/etc/udev/rules.d/030qosmotec-dccs.rules[5]' applied, added symlink 'card_not_usable'
Feb  9 21:15:14 dccs75 udev[23203]: creating device node '/dev/ttyUSB4'
Feb  9 21:17:01 dccs75 /USR/SBIN/CRON[23227]: (root) CMD (   run-parts --report /etc/cron.hourly)
Feb  9 21:19:07 dccs75 kernel: ohci_hcd 0000:2c:00.0: remove, state 1
Feb  9 21:19:07 dccs75 kernel: usb usb5: USB disconnect, address 1
Feb  9 21:19:07 dccs75 kernel: usb 5-1: USB disconnect, address 5
Feb  9 21:19:07 dccs75 kernel: usbserial_generic 5-1:1.0: device disconnected
Feb  9 21:19:07 dccs75 kernel: generic ttyUSB5: Generic converter now disconnected from ttyUSB5
Feb  9 21:19:07 dccs75 kernel: usbserial_generic 5-1:1.1: device disconnected
Feb  9 21:19:07 dccs75 kernel: generic ttyUSB4: Generic converter now disconnected from ttyUSB4
Feb  9 21:19:07 dccs75 kernel: ohci_hcd 0000:2c:00.0: USB bus 5 deregistered
Feb  9 21:19:07 dccs75 kernel: ACPI: PCI interrupt for device 0000:2c:00.0 disabled
Feb  9 21:19:07 dccs75 kernel: ohci_hcd 0000:2c:00.1: remove, state 1
Feb  9 21:19:07 dccs75 kernel: usb usb6: USB disconnect, address 1
Feb  9 21:19:07 dccs75 kernel: ohci_hcd 0000:2c:00.1: USB bus 6 deregistered
Feb  9 21:19:07 dccs75 kernel: ACPI: PCI interrupt for device 0000:2c:00.1 disabled
Feb  9 21:19:07 dccs75 udev[23277]: removing device node '/dev/usbdev5.5'
Feb  9 21:19:07 dccs75 udev[23276]: removing device node '/dev/ttyUSB4'
Feb  9 21:19:07 dccs75 udev[23298]: removing device node '/dev/usbdev5.1'
Feb  9 21:19:08 dccs75 udev[23268]: removing device node '/dev/ttyUSB5'
Feb  9 21:19:08 dccs75 udev[23323]: removing device node '/dev/usbdev6.1'
Feb  9 21:19:38 dccs75 syslog-ng[5822]: STATS: dropped 0
Feb  9 21:20:01 dccs75 /USR/SBIN/CRON[23433]: (root) CMD (/usr/sbin/ntpdate 192.168.190.65)
Feb  9 21:21:15 dccs75 kernel: PCI: Found 0000:2c:00.0 [1033/0035] 000c03 00
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c01e9580 for 0000:2c:00.0
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c01e9b10 for 0000:2c:00.0
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c027d0b0 for 0000:2c:00.0
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c027d480 for 0000:2c:00.0
Feb  9 21:21:15 dccs75 kernel: PCI: Found 0000:2c:00.1 [1033/0035] 000c03 00
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c01e9580 for 0000:2c:00.1
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c01e9b10 for 0000:2c:00.1
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c027d0b0 for 0000:2c:00.1
Feb  9 21:21:15 dccs75 kernel: PCI: Calling quirk c027d480 for 0000:2c:00.1
Feb  9 21:21:15 dccs75 kernel: got res [f9017000:f9017fff] bus [f9017000:f9017fff] flags 200 for BAR 0 of 0000:2c:00.0
Feb  9 21:21:15 dccs75 kernel: PCI: moved device 0000:2c:00.0 resource 0 (200) to f9017000
Feb  9 21:21:15 dccs75 kernel: got res [f9018000:f9018fff] bus [f9018000:f9018fff] flags 200 for BAR 0 of 0000:2c:00.1
Feb  9 21:21:15 dccs75 kernel: PCI: moved device 0000:2c:00.1 resource 0 (200) to f9018000
Feb  9 21:21:15 dccs75 kernel: PCI: Enabling device 0000:2c:00.0 (0000 -> 0002)
Feb  9 21:21:15 dccs75 kernel: ACPI: PCI Interrupt 0000:2c:00.0[A] -> GSI 56 (level, low) -> IRQ 193
Feb  9 21:21:15 dccs75 kernel: PCI: Enabling bus mastering for device 0000:2c:00.0
Feb  9 21:21:15 dccs75 kernel: PCI: Setting latency timer of device 0000:2c:00.0 to 64
Feb  9 21:21:15 dccs75 kernel: ohci_hcd 0000:2c:00.0: OHCI Host Controller
Feb  9 21:21:15 dccs75 kernel: ohci_hcd 0000:2c:00.0: new USB bus registered, assigned bus number 5
Feb  9 21:21:15 dccs75 kernel: ohci_hcd 0000:2c:00.0: irq 193, io mem 0xf9017000
Feb  9 21:21:15 dccs75 kernel: hub 5-0:1.0: USB hub found
Feb  9 21:21:15 dccs75 kernel: hub 5-0:1.0: 3 ports detected
Feb  9 21:21:15 dccs75 kernel: PCI: Enabling device 0000:2c:00.1 (0000 -> 0002)
Feb  9 21:21:15 dccs75 kernel: ACPI: PCI Interrupt 0000:2c:00.1[B] -> GSI 56 (level, low) -> IRQ 193
Feb  9 21:21:15 dccs75 kernel: PCI: Enabling bus mastering for device 0000:2c:00.1
Feb  9 21:21:15 dccs75 kernel: PCI: Setting latency timer of device 0000:2c:00.1 to 64
Feb  9 21:21:15 dccs75 kernel: ohci_hcd 0000:2c:00.1: OHCI Host Controller
Feb  9 21:21:15 dccs75 kernel: ohci_hcd 0000:2c:00.1: new USB bus registered, assigned bus number 6
Feb  9 21:21:15 dccs75 kernel: ohci_hcd 0000:2c:00.1: irq 193, io mem 0xf9018000
Feb  9 21:21:15 dccs75 kernel: hub 6-0:1.0: USB hub found
Feb  9 21:21:15 dccs75 kernel: hub 6-0:1.0: 2 ports detected
Feb  9 21:21:16 dccs75 pci.agent[23449]:      ohci-hcd: already loaded
Feb  9 21:21:16 dccs75 kernel: usb 5-1: new low speed USB device using ohci_hcd and address 2
Feb  9 21:21:16 dccs75 pci.agent[23466]:      ohci-hcd: already loaded
Feb  9 21:21:16 dccs75 usb.agent[23506]:      usbcore: already loaded
Feb  9 21:21:16 dccs75 udev[23577]: creating device node '/dev/usbdev5.1'
Feb  9 21:21:16 dccs75 usb.agent[23549]:      usbcore: already loaded
Feb  9 21:21:16 dccs75 udev[23596]: creating device node '/dev/usbdev6.1'
Feb  9 21:21:17 dccs75 kernel: ohci_hcd 0000:2c:00.0: Unlink after no-IRQ?  Controller is probably using the wrong IRQ.
Feb  9 21:23:38 dccs75 kernel: ohci_hcd 0000:2c:00.0: remove, state 1
Feb  9 21:23:38 dccs75 kernel: hub 6-0:1.0: resubmit --> -108
Feb  9 21:24:09 dccs75 dhclient: DHCPREQUEST on eth0 to 192.168.190.65 port 67
Feb  9 21:24:09 dccs75 dhclient: DHCPACK from 192.168.190.65
Feb  9 21:24:09 dccs75 dhclient: bound to 192.168.190.75 -- renewal in 300 seconds.
Feb  9 21:25:01 dccs75 /USR/SBIN/CRON[23614]: (root) CMD (/usr/sbin/ntpdate 192.168.190.65)
Feb  9 21:25:24 dccs75 shutdown[23618]: shutting down for system reboot
Feb  9 21:25:24 dccs75 init: Switching to runlevel: 6

You see it works normally, then Unlink after no-IRQ? happens; after that
the pcmcia-card is not usable anymore and only a reboot resolves this
problem. Any idea?


The System:
debian stable/testing 
kernel 2.6.24.4
pcmciautils 012-3

We use a script which has the lines

echo "1" > /sys/class/pcmcia/pcmcia_socket0/card_eject
resp.
echo "1" > /sys/class/pcmcia/pcmcia_socket0/card_insert


for insert/eject
(We need a special script, because we want always the same device name
for the card which is inserted in that certain slot)

with kind regards

Sebastian Günther
network administrator

-- 
Qosmotec Software Solutions GmbH     QQQQ       Tel: + 49.241.879 75 10
Schloss-Rahe-Strasse 15             Q _\ Q      Mob: + 49.177.657 76 69
52072 Aix La Chapelle (Aachen)      Q \ \Q      Fax: + 49.241.879 75 15
Germany                              QQ\_\      http://www.qosmotec.com

More information about the linux-pcmcia mailing list