Hi folks !
My USB GSM modem (Huawei 169, pretty common stuff) stopped working in
the latest ubuntu karmic update. So far, I tracked it down to a
regression that happened in the stable releases between 2.6.31.1 and
2.6.31.2 (still present in .3). I haven't tested 2.6.32-rc* yet and
haven't had a chance to bisect (need to make myself a trimmed
down .config first).
There's a lot of usb-serial changes in there. At first glance, I'd say
you guys are taking chances in a stable release for stuff that hasn't
been out in the main "upstream" release for some time but heh :-)
The symptom is that the USB modem just disconnects/reconnects in a loop.
The log looks like what I pasted below when plugging the device (and
leaving it in, the disconnects don't correspond to the device being
removed).
Note that 2.6.31.1 works but tends to oops on removal of the device,
I'll paste the oops log too.
Next, as time permits, I'll test upstream and if you think it's worth it
try to bisect the .2 problem down to one of the numerous usb-serial
changes in there.
Cheers,
Ben.
Oct 10 11:07:03 pasglop kernel: [ 49.144079] usb 4-1: new full speed USB device using uhci_hcd and address 2
Oct 10 11:07:03 pasglop kernel: [ 49.305220] usb 4-1: configuration #1 chosen from 1 choice
Oct 10 11:07:04 pasglop kernel: [ 49.317562] Initializing USB Mass Storage driver...
Oct 10 11:07:04 pasglop kernel: [ 49.319184] scsi2 : SCSI emulation for USB Mass Storage devices
Oct 10 11:07:04 pasglop kernel: [ 49.319322] usbcore: registered new interface driver usb-storage
Oct 10 11:07:04 pasglop kernel: [ 49.319326] USB Mass Storage support registered.
Oct 10 11:07:04 pasglop kernel: [ 49.320661] usb-storage: device found at 2
Oct 10 11:07:04 pasglop kernel: [ 49.320664] usb-storage: waiting for device to settle before scanning
Oct 10 11:07:04 pasglop kernel: [ 49.504146] usb 4-1: USB disconnect, address 2
Oct 10 11:07:04 pasglop kernel: [ 50.296066] usb 4-1: new full speed USB device using uhci_hcd and address 3
Oct 10 11:07:04 pasglop kernel: [ 50.457214] usb 4-1: configuration #1 chosen from 1 choice
Oct 10 11:07:04 pasglop kernel: [ 50.478880] usbcore: registered new interface driver usbserial
Oct 10 11:07:04 pasglop kernel: [ 50.479309] USB Serial support registered for generic
Oct 10 11:07:04 pasglop kernel: [ 50.492138] scsi6 : SCSI emulation for USB Mass Storage devices
Oct 10 11:07:04 pasglop kernel: [ 50.493166] usbcore: registered new interface driver usbserial_generic
Oct 10 11:07:04 pasglop kernel: [ 50.493170] usbserial: USB Serial Driver core
Oct 10 11:07:04 pasglop kernel: [ 50.497581] USB Serial support registered for GSM modem (1-port)
Oct 10 11:07:04 pasglop kernel: [ 50.497626] option 4-1:1.0: GSM modem (1-port) converter detected
Oct 10 11:07:04 pasglop kernel: [ 50.497712] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB0
Oct 10 11:07:04 pasglop kernel: [ 50.497723] option 4-1:1.1: GSM modem (1-port) converter detected
Oct 10 11:07:04 pasglop kernel: [ 50.497772] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB1
Oct 10 11:07:04 pasglop kernel: [ 50.497782] option 4-1:1.2: GSM modem (1-port) converter detected
Oct 10 11:07:04 pasglop kernel: [ 50.497841] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB2
Oct 10 11:07:04 pasglop kernel: [ 50.497859] usbcore: registered new interface driver option
Oct 10 11:07:09 pasglop kernel: [ 50.497861] option: v0.7.2:USB Driver for GSM modems
Oct 10 11:07:09 pasglop kernel: [ 50.502750] usb-storage: device found at 3
Oct 10 11:07:09 pasglop kernel: [ 50.502753] usb-storage: waiting for device to settle before scanning
Oct 10 11:07:09 pasglop kernel: [ 55.501229] usb-storage: device scan complete
Oct 10 11:07:09 pasglop kernel: [ 55.504147] scsi 6:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
Oct 10 11:07:09 pasglop kernel: [ 55.507170] scsi 6:0:0:1: Direct-Access HUAWEI SD Storage 2.31 PQ: 0 ANSI: 2
Oct 10 11:07:09 pasglop kernel: [ 55.530139] sr1: scsi-1 drive
Oct 10 11:07:09 pasglop kernel: [ 55.530341] sr 6:0:0:0: Attached scsi CD-ROM sr1
Oct 10 11:07:09 pasglop kernel: [ 55.531248] sr 6:0:0:0: Attached scsi generic sg2 type 5
Oct 10 11:07:09 pasglop kernel: [ 55.531376] sd 6:0:0:1: Attached scsi generic sg3 type 0
Oct 10 11:07:09 pasglop kernel: [ 55.554127] option: option_instat_callback: error -108
Oct 10 11:07:09 pasglop kernel: [ 55.554232] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Oct 10 11:07:09 pasglop kernel: [ 55.554254] option 4-1:1.0: device disconnected
Oct 10 11:07:09 pasglop kernel: [ 55.557199] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Oct 10 11:07:09 pasglop kernel: [ 55.557215] option 4-1:1.1: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 55.557284] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Oct 10 11:07:10 pasglop kernel: [ 55.557303] option 4-1:1.2: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 55.669058] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:07:10 pasglop kernel: [ 55.819263] option 4-1:1.2: GSM modem (1-port) converter detected
Oct 10 11:07:10 pasglop kernel: [ 55.819339] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB0
Oct 10 11:07:10 pasglop kernel: [ 55.820552] option 4-1:1.1: GSM modem (1-port) converter detected
Oct 10 11:07:10 pasglop kernel: [ 55.820616] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB1
Oct 10 11:07:10 pasglop kernel: [ 55.821460] option 4-1:1.0: GSM modem (1-port) converter detected
Oct 10 11:07:10 pasglop kernel: [ 55.821522] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB2
Oct 10 11:07:10 pasglop kernel: [ 55.839093] option: option_instat_callback: error -108
Oct 10 11:07:10 pasglop kernel: [ 55.839209] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Oct 10 11:07:10 pasglop kernel: [ 55.839228] option 4-1:1.0: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 55.839289] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Oct 10 11:07:10 pasglop kernel: [ 55.839306] option 4-1:1.1: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 55.839366] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Oct 10 11:07:10 pasglop kernel: [ 55.839382] option 4-1:1.2: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 56.008068] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:07:10 pasglop kernel: [ 56.156255] option 4-1:1.2: GSM modem (1-port) converter detected
Oct 10 11:07:10 pasglop kernel: [ 56.156337] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB0
Oct 10 11:07:10 pasglop kernel: [ 56.156434] option 4-1:1.1: GSM modem (1-port) converter detected
Oct 10 11:07:10 pasglop kernel: [ 56.156488] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB1
Oct 10 11:07:10 pasglop kernel: [ 56.159274] option 4-1:1.0: GSM modem (1-port) converter detected
Oct 10 11:07:10 pasglop kernel: [ 56.159346] usb 4-1: GSM modem (1-port) converter now attached to ttyUSB2
Oct 10 11:07:10 pasglop kernel: [ 56.180094] option: option_instat_callback: error -108
Oct 10 11:07:10 pasglop kernel: [ 56.180190] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Oct 10 11:07:10 pasglop kernel: [ 56.180209] option 4-1:1.0: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 56.180290] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Oct 10 11:07:10 pasglop kernel: [ 56.180307] option 4-1:1.1: device disconnected
Oct 10 11:07:10 pasglop kernel: [ 56.180374] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Oct 10 11:07:10 pasglop kernel: [ 56.180390] option 4-1:1.2: device disconnected
etc... in a loop.
The oops log with .1 is:
Oct 10 11:09:33 pasglop kernel: [ 92.409225] usb 4-1: USB disconnect, address 4
Oct 10 11:09:33 pasglop kernel: [ 92.410299] option: option_instat_callback: error -108
Oct 10 11:09:33 pasglop kernel: [ 92.410691] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Oct 10 11:09:33 pasglop kernel: [ 92.410726] option 4-1:1.0: device disconnected
Oct 10 11:09:33 pasglop kernel: [ 92.411023] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Oct 10 11:09:33 pasglop kernel: [ 92.411054] option 4-1:1.1: device disconnected
Oct 10 11:09:33 pasglop kernel: [ 92.411364] option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Oct 10 11:09:33 pasglop kernel: [ 92.411409] option 4-1:1.2: device disconnected
Oct 10 11:09:33 pasglop kernel: [ 93.445278] BUG: unable to handle kernel paging request at 349a46ed
Oct 10 11:09:33 pasglop kernel: [ 93.445294] IP: [<f96dee98>] serial_do_free+0x38/0x80 [usbserial]
Oct 10 11:09:33 pasglop kernel: [ 93.445319] *pde = 00000000
Oct 10 11:09:33 pasglop kernel: [ 93.445327] Oops: 0000 [#1] SMP
Oct 10 11:09:33 pasglop kernel: [ 93.445336] last sysfs file: /sys/devices/pci0000:00/0000:00:1c.1/0000:03:00.0/ieee80211/phy0/rfkill2/uevent
Oct 10 11:09:33 pasglop kernel: [ 93.445344] Modules linked in: ppp_async crc_ccitt option usbserial usb_storage aes_i586 aes_generic binfmt_misc bridge stp ppdev bnep snd_hda_codec_analog joydev fbcon tileblit font bitblit softcursor snd_hda_intel snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event arc4 ecb snd_seq snd_timer iptable_filter psmouse pcmcia ip_tables snd_seq_device iwlagn iwlcore mac80211 sdhci_pci serio_raw i915 x_tables snd thinkpad_acpi yenta_socket drm i2c_algo_bit soundcore sdhci btusb snd_page_alloc led_class nvram video rsrc_nonstatic ricoh_mmc pcmcia_core intel_agp cfg80211 output agpgart lp parport ohci1394 ieee1394 e1000e
Oct 10 11:09:33 pasglop kernel: [ 93.445495]
Oct 10 11:09:33 pasglop kernel: [ 93.445503] Pid: 2085, comm: pppd Not tainted (2.6.31-02063101-generic #02063101) 7659AB8
Oct 10 11:09:33 pasglop kernel: [ 93.445511] EIP: 0060:[<f96dee98>] EFLAGS: 00010246 CPU: 1
Oct 10 11:09:33 pasglop kernel: [ 93.445528] EIP is at serial_do_free+0x38/0x80 [usbserial]
Oct 10 11:09:33 pasglop kernel: [ 93.445535] EAX: 349a46d1 EBX: f343e960 ECX: 00000000 EDX: f3ffc000
Oct 10 11:09:33 pasglop kernel: [ 93.445542] ESI: f343e998 EDI: f4601198 EBP: f265fe84 ESP: f265fe78
Oct 10 11:09:33 pasglop kernel: [ 93.445548] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
Oct 10 11:09:33 pasglop kernel: [ 93.445556] Process pppd (pid: 2085, ti=f265e000 task=f327b240 task.ti=f265e000)
Oct 10 11:09:33 pasglop kernel: [ 93.445561] Stack:
Oct 10 11:09:33 pasglop kernel: [ 93.445565] f3ffc000 f250b800 f4601198 f265feac f96def1b f265feac c037b2db f250b8b4
Oct 10 11:09:33 pasglop kernel: [ 93.445584] <0> 00000000 f3c0fd00 f250b800 00000000 f4601198 f265ff38 c037ceb1 f265ff38
Oct 10 11:09:33 pasglop kernel: [ 93.445604] <0> f265fedc f265fed0 c015d9f3 f265fed0 f3c0fd00 00000000 f6672cd8 c015e43a
Oct 10 11:09:33 pasglop kernel: [ 93.445626] Call Trace:
Oct 10 11:09:33 pasglop kernel: [ 93.445645] [<f96def1b>] ? serial_close+0x3b/0xa0 [usbserial]
Oct 10 11:09:33 pasglop kernel: [ 93.445660] [<c037b2db>] ? tty_fasync+0x3b/0x110
Oct 10 11:09:33 pasglop kernel: [ 93.445670] [<c037ceb1>] ? tty_release_dev+0x151/0x4b0
Oct 10 11:09:33 pasglop kernel: [ 93.445681] [<c015d9f3>] ? lock_hrtimer_base+0x23/0x50
Oct 10 11:09:33 pasglop kernel: [ 93.445690] [<c015e43a>] ? hrtimer_try_to_cancel+0x3a/0x80
Oct 10 11:09:33 pasglop kernel: [ 93.445700] [<c015e491>] ? hrtimer_cancel+0x11/0x20
Oct 10 11:09:33 pasglop kernel: [ 93.445710] [<c05670af>] ? do_nanosleep+0x8f/0xc0
Oct 10 11:09:33 pasglop kernel: [ 93.445719] [<c015e5b9>] ? hrtimer_nanosleep+0x99/0x120
Oct 10 11:09:33 pasglop kernel: [ 93.445738] [<c037d222>] ? tty_release+0x12/0x20
Oct 10 11:09:33 pasglop kernel: [ 93.445749] [<c01e610a>] ? __fput+0xda/0x1f0
Oct 10 11:09:33 pasglop kernel: [ 93.445758] [<c01e6439>] ? fput+0x19/0x20
Oct 10 11:09:33 pasglop kernel: [ 93.445767] [<c01e3027>] ? filp_close+0x47/0x70
Oct 10 11:09:33 pasglop kernel: [ 93.445778] [<c01f2744>] ? do_vfs_ioctl+0x64/0x1c0
Oct 10 11:09:33 pasglop kernel: [ 93.445787] [<c01e43d9>] ? sys_close+0x69/0xb0
Oct 10 11:09:33 pasglop kernel: [ 93.445797] [<c0102ee3>] ? sysenter_do_call+0x12/0x28
Oct 10 11:09:33 pasglop kernel: [ 93.445803] Code: 24 04 89 7c 24 08 80 b8 da 00 00 00 00 74 14 8b 1c 24 8b 74 24 04 8b 7c 24 08 89 ec 5d c3 90 8d 74 26 00 8b 18 8b 43 04 8d 73 38 <8b> 78 1c 8d 82 e0 00 00 00 e8 3a d5 cb c6 89 f0 e8 23 7d e8 c6
Cheers,
Ben.
On Sat, 2009-10-10 at 11:25 +1100, Benjamin Herrenschmidt wrote:
> Hi folks !
>
> My USB GSM modem (Huawei 169, pretty common stuff) stopped working in
> the latest ubuntu karmic update. So far, I tracked it down to a
> regression that happened in the stable releases between 2.6.31.1 and
> 2.6.31.2 (still present in .3). I haven't tested 2.6.32-rc* yet and
> haven't had a chance to bisect (need to make myself a trimmed
> down .config first).
2.6.32-rc3 is also busted with a different log output:
Oct 10 11:27:36 pasglop kernel: [ 34.480060] usb 4-1: new full speed USB device using uhci_hcd and address 2
Oct 10 11:27:36 pasglop kernel: [ 34.645057] usb 4-1: configuration #1 chosen from 1 choice
Oct 10 11:27:36 pasglop kernel: [ 34.658115] Initializing USB Mass Storage driver...
Oct 10 11:27:36 pasglop kernel: [ 34.660006] scsi2 : SCSI emulation for USB Mass Storage devices
Oct 10 11:27:36 pasglop kernel: [ 34.660290] usbcore: registered new interface driver usb-storage
Oct 10 11:27:36 pasglop kernel: [ 34.660294] USB Mass Storage support registered.
Oct 10 11:27:36 pasglop kernel: [ 34.661566] usb-storage: device found at 2
Oct 10 11:27:36 pasglop kernel: [ 34.661568] usb-storage: waiting for device to settle before scanning
Oct 10 11:27:36 pasglop kernel: [ 35.100131] usb 4-1: USB disconnect, address 2
Oct 10 11:27:36 pasglop kernel: [ 35.345076] usb 4-1: new full speed USB device using uhci_hcd and address 3
Oct 10 11:27:41 pasglop kernel: [ 35.503633] usb 4-1: configuration #1 chosen from 1 choice
Oct 10 11:27:41 pasglop kernel: [ 35.515533] scsi6 : SCSI emulation for USB Mass Storage devices
Oct 10 11:27:41 pasglop kernel: [ 35.516567] usb-storage: device found at 3
Oct 10 11:27:41 pasglop kernel: [ 35.516569] usb-storage: waiting for device to settle before scanning
Oct 10 11:27:41 pasglop kernel: [ 40.518055] usb-storage: device scan complete
Oct 10 11:27:41 pasglop kernel: [ 40.521051] scsi 6:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
Oct 10 11:27:41 pasglop kernel: [ 40.524065] scsi 6:0:0:1: Direct-Access HUAWEI SD Storage 2.31 PQ: 0 ANSI: 2
Oct 10 11:27:41 pasglop kernel: [ 40.546018] sr1: scsi-1 drive
Oct 10 11:27:43 pasglop kernel: [ 40.547167] sr 6:0:0:0: Attached scsi CD-ROM sr1
Oct 10 11:27:43 pasglop kernel: [ 40.548872] sr 6:0:0:0: Attached scsi generic sg2 type 5
Oct 10 11:27:43 pasglop kernel: [ 40.549178] sd 6:0:0:1: Attached scsi generic sg3 type 0
Oct 10 11:27:43 pasglop kernel: [ 40.681084] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:43 pasglop kernel: [ 40.960039] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:43 pasglop kernel: [ 41.233071] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:43 pasglop kernel: [ 41.509066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:44 pasglop kernel: [ 41.784064] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:44 pasglop kernel: [ 42.057066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:44 pasglop kernel: [ 42.329066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:44 pasglop kernel: [ 42.613070] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:44 pasglop kernel: [ 42.888112] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:44 pasglop kernel: [ 43.160070] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:46 pasglop kernel: [ 43.433054] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:46 pasglop kernel: [ 43.705212] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:46 pasglop kernel: [ 43.981068] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:46 pasglop kernel: [ 44.257074] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:46 pasglop kernel: [ 44.536063] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:46 pasglop kernel: [ 44.813088] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:48 pasglop kernel: [ 45.085065] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:48 pasglop kernel: [ 45.357085] usb 4-1: reset full speed USB device using uhci_hcd and address 3
.../... (more of these)
Oct 10 11:27:51 pasglop kernel: [ 48.779909] sd 6:0:0:1: [sdb] Attached SCSI removable disk
Oct 10 11:27:51 pasglop kernel: [ 48.904062] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:51 pasglop kernel: [ 49.174068] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:51 pasglop kernel: [ 49.445548] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 49.717290] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 49.985098] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 50.268061] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 50.544107] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 50.817073] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 51.088083] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:52 pasglop kernel: [ 51.356079] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:54 pasglop kernel: [ 51.625086] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:54 pasglop kernel: [ 51.893071] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:54 pasglop kernel: [ 52.161084] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:54 pasglop kernel: [ 52.429060] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:54 pasglop kernel: [ 52.701104] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:27:54 pasglop kernel: [ 52.969058] usb 4-1: reset full speed USB device using uhci_hcd and address 3
.../... (more of these)
Oct 10 11:28:21 pasglop kernel: [ 79.889107] usb 4-1: reset full speed USB device using uhci_hcd and address 3
Oct 10 11:28:21 pasglop kernel: [ 79.945827] usb 4-1: USB disconnect, address 3
Oct 10 11:28:21 pasglop kernel: [ 79.950827] sr 6:0:0:0: [sr1] Unhandled error code
Oct 10 11:28:21 pasglop kernel: [ 79.950836] sr 6:0:0:0: [sr1] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Oct 10 11:28:21 pasglop kernel: [ 79.950846] sr 6:0:0:0: [sr1] CDB: Read(10): 28 00 00 00 00 c6 00 00 20 00
Oct 10 11:28:21 pasglop kernel: [ 79.950872] end_request: I/O error, dev sr1, sector 792
Oct 10 11:28:21 pasglop kernel: [ 79.950883] Buffer I/O error on device sr1, logical block 792
Oct 10 11:28:21 pasglop kernel: [ 79.950892] Buffer I/O error on device sr1, logical block 793
Oct 10 11:28:21 pasglop kernel: [ 79.950899] Buffer I/O error on device sr1, logical block 794
Oct 10 11:28:21 pasglop kernel: [ 79.950906] Buffer I/O error on device sr1, logical block 795
Oct 10 11:28:21 pasglop kernel: [ 79.950913] Buffer I/O error on device sr1, logical block 796
Oct 10 11:28:21 pasglop kernel: [ 79.950921] Buffer I/O error on device sr1, logical block 797
Oct 10 11:28:21 pasglop kernel: [ 79.950927] Buffer I/O error on device sr1, logical block 798
At the end, I think I yanked it out.
Cheers,
Ben.
(Adding Rafael)
On Sat, 2009-10-10 at 11:31 +1100, Benjamin Herrenschmidt wrote:
> On Sat, 2009-10-10 at 11:25 +1100, Benjamin Herrenschmidt wrote:
> > Hi folks !
> >
> > My USB GSM modem (Huawei 169, pretty common stuff) stopped working in
> > the latest ubuntu karmic update. So far, I tracked it down to a
> > regression that happened in the stable releases between 2.6.31.1 and
> > 2.6.31.2 (still present in .3). I haven't tested 2.6.32-rc* yet and
> > haven't had a chance to bisect (need to make myself a trimmed
> > down .config first).
>
> 2.6.32-rc3 is also busted with a different log output:
>
> Oct 10 11:27:36 pasglop kernel: [ 34.480060] usb 4-1: new full speed USB device using uhci_hcd and address 2
> Oct 10 11:27:36 pasglop kernel: [ 34.645057] usb 4-1: configuration #1 chosen from 1 choice
> Oct 10 11:27:36 pasglop kernel: [ 34.658115] Initializing USB Mass Storage driver...
> Oct 10 11:27:36 pasglop kernel: [ 34.660006] scsi2 : SCSI emulation for USB Mass Storage devices
> Oct 10 11:27:36 pasglop kernel: [ 34.660290] usbcore: registered new interface driver usb-storage
> Oct 10 11:27:36 pasglop kernel: [ 34.660294] USB Mass Storage support registered.
> Oct 10 11:27:36 pasglop kernel: [ 34.661566] usb-storage: device found at 2
> Oct 10 11:27:36 pasglop kernel: [ 34.661568] usb-storage: waiting for device to settle before scanning
> Oct 10 11:27:36 pasglop kernel: [ 35.100131] usb 4-1: USB disconnect, address 2
> Oct 10 11:27:36 pasglop kernel: [ 35.345076] usb 4-1: new full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:41 pasglop kernel: [ 35.503633] usb 4-1: configuration #1 chosen from 1 choice
> Oct 10 11:27:41 pasglop kernel: [ 35.515533] scsi6 : SCSI emulation for USB Mass Storage devices
> Oct 10 11:27:41 pasglop kernel: [ 35.516567] usb-storage: device found at 3
> Oct 10 11:27:41 pasglop kernel: [ 35.516569] usb-storage: waiting for device to settle before scanning
> Oct 10 11:27:41 pasglop kernel: [ 40.518055] usb-storage: device scan complete
> Oct 10 11:27:41 pasglop kernel: [ 40.521051] scsi 6:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
> Oct 10 11:27:41 pasglop kernel: [ 40.524065] scsi 6:0:0:1: Direct-Access HUAWEI SD Storage 2.31 PQ: 0 ANSI: 2
> Oct 10 11:27:41 pasglop kernel: [ 40.546018] sr1: scsi-1 drive
> Oct 10 11:27:43 pasglop kernel: [ 40.547167] sr 6:0:0:0: Attached scsi CD-ROM sr1
> Oct 10 11:27:43 pasglop kernel: [ 40.548872] sr 6:0:0:0: Attached scsi generic sg2 type 5
> Oct 10 11:27:43 pasglop kernel: [ 40.549178] sd 6:0:0:1: Attached scsi generic sg3 type 0
> Oct 10 11:27:43 pasglop kernel: [ 40.681084] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:43 pasglop kernel: [ 40.960039] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:43 pasglop kernel: [ 41.233071] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:43 pasglop kernel: [ 41.509066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:44 pasglop kernel: [ 41.784064] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:44 pasglop kernel: [ 42.057066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:44 pasglop kernel: [ 42.329066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:44 pasglop kernel: [ 42.613070] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:44 pasglop kernel: [ 42.888112] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:44 pasglop kernel: [ 43.160070] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:46 pasglop kernel: [ 43.433054] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:46 pasglop kernel: [ 43.705212] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:46 pasglop kernel: [ 43.981068] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:46 pasglop kernel: [ 44.257074] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:46 pasglop kernel: [ 44.536063] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:46 pasglop kernel: [ 44.813088] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:48 pasglop kernel: [ 45.085065] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:48 pasglop kernel: [ 45.357085] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> .../... (more of these)
> Oct 10 11:27:51 pasglop kernel: [ 48.779909] sd 6:0:0:1: [sdb] Attached SCSI removable disk
> Oct 10 11:27:51 pasglop kernel: [ 48.904062] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:51 pasglop kernel: [ 49.174068] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:51 pasglop kernel: [ 49.445548] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 49.717290] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 49.985098] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 50.268061] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 50.544107] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 50.817073] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 51.088083] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:52 pasglop kernel: [ 51.356079] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:54 pasglop kernel: [ 51.625086] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:54 pasglop kernel: [ 51.893071] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:54 pasglop kernel: [ 52.161084] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:54 pasglop kernel: [ 52.429060] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:54 pasglop kernel: [ 52.701104] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:27:54 pasglop kernel: [ 52.969058] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> .../... (more of these)
> Oct 10 11:28:21 pasglop kernel: [ 79.889107] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> Oct 10 11:28:21 pasglop kernel: [ 79.945827] usb 4-1: USB disconnect, address 3
> Oct 10 11:28:21 pasglop kernel: [ 79.950827] sr 6:0:0:0: [sr1] Unhandled error code
> Oct 10 11:28:21 pasglop kernel: [ 79.950836] sr 6:0:0:0: [sr1] Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
> Oct 10 11:28:21 pasglop kernel: [ 79.950846] sr 6:0:0:0: [sr1] CDB: Read(10): 28 00 00 00 00 c6 00 00 20 00
> Oct 10 11:28:21 pasglop kernel: [ 79.950872] end_request: I/O error, dev sr1, sector 792
> Oct 10 11:28:21 pasglop kernel: [ 79.950883] Buffer I/O error on device sr1, logical block 792
> Oct 10 11:28:21 pasglop kernel: [ 79.950892] Buffer I/O error on device sr1, logical block 793
> Oct 10 11:28:21 pasglop kernel: [ 79.950899] Buffer I/O error on device sr1, logical block 794
> Oct 10 11:28:21 pasglop kernel: [ 79.950906] Buffer I/O error on device sr1, logical block 795
> Oct 10 11:28:21 pasglop kernel: [ 79.950913] Buffer I/O error on device sr1, logical block 796
> Oct 10 11:28:21 pasglop kernel: [ 79.950921] Buffer I/O error on device sr1, logical block 797
> Oct 10 11:28:21 pasglop kernel: [ 79.950927] Buffer I/O error on device sr1, logical block 798
>
> At the end, I think I yanked it out.
>
> Cheers,
> Ben.
>
On Sat, 10 Oct 2009, Benjamin Herrenschmidt wrote:
> (Adding Rafael)
>
> On Sat, 2009-10-10 at 11:31 +1100, Benjamin Herrenschmidt wrote:
> > On Sat, 2009-10-10 at 11:25 +1100, Benjamin Herrenschmidt wrote:
> > > Hi folks !
> > >
> > > My USB GSM modem (Huawei 169, pretty common stuff) stopped working in
> > > the latest ubuntu karmic update. So far, I tracked it down to a
> > > regression that happened in the stable releases between 2.6.31.1 and
> > > 2.6.31.2 (still present in .3). I haven't tested 2.6.32-rc* yet and
> > > haven't had a chance to bisect (need to make myself a trimmed
> > > down .config first).
> >
> > 2.6.32-rc3 is also busted with a different log output:
> >
> > Oct 10 11:27:36 pasglop kernel: [ 34.480060] usb 4-1: new full speed USB device using uhci_hcd and address 2
> > Oct 10 11:27:36 pasglop kernel: [ 34.645057] usb 4-1: configuration #1 chosen from 1 choice
> > Oct 10 11:27:36 pasglop kernel: [ 34.658115] Initializing USB Mass Storage driver...
> > Oct 10 11:27:36 pasglop kernel: [ 34.660006] scsi2 : SCSI emulation for USB Mass Storage devices
> > Oct 10 11:27:36 pasglop kernel: [ 34.660290] usbcore: registered new interface driver usb-storage
> > Oct 10 11:27:36 pasglop kernel: [ 34.660294] USB Mass Storage support registered.
> > Oct 10 11:27:36 pasglop kernel: [ 34.661566] usb-storage: device found at 2
> > Oct 10 11:27:36 pasglop kernel: [ 34.661568] usb-storage: waiting for device to settle before scanning
> > Oct 10 11:27:36 pasglop kernel: [ 35.100131] usb 4-1: USB disconnect, address 2
> > Oct 10 11:27:36 pasglop kernel: [ 35.345076] usb 4-1: new full speed USB device using uhci_hcd and address 3
> > Oct 10 11:27:41 pasglop kernel: [ 35.503633] usb 4-1: configuration #1 chosen from 1 choice
> > Oct 10 11:27:41 pasglop kernel: [ 35.515533] scsi6 : SCSI emulation for USB Mass Storage devices
> > Oct 10 11:27:41 pasglop kernel: [ 35.516567] usb-storage: device found at 3
> > Oct 10 11:27:41 pasglop kernel: [ 35.516569] usb-storage: waiting for device to settle before scanning
> > Oct 10 11:27:41 pasglop kernel: [ 40.518055] usb-storage: device scan complete
> > Oct 10 11:27:41 pasglop kernel: [ 40.521051] scsi 6:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
> > Oct 10 11:27:41 pasglop kernel: [ 40.524065] scsi 6:0:0:1: Direct-Access HUAWEI SD Storage 2.31 PQ: 0 ANSI: 2
> > Oct 10 11:27:41 pasglop kernel: [ 40.546018] sr1: scsi-1 drive
> > Oct 10 11:27:43 pasglop kernel: [ 40.547167] sr 6:0:0:0: Attached scsi CD-ROM sr1
> > Oct 10 11:27:43 pasglop kernel: [ 40.548872] sr 6:0:0:0: Attached scsi generic sg2 type 5
> > Oct 10 11:27:43 pasglop kernel: [ 40.549178] sd 6:0:0:1: Attached scsi generic sg3 type 0
> > Oct 10 11:27:43 pasglop kernel: [ 40.681084] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> > Oct 10 11:27:43 pasglop kernel: [ 40.960039] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> > Oct 10 11:27:43 pasglop kernel: [ 41.233071] usb 4-1: reset full speed USB device using uhci_hcd and address 3
> > Oct 10 11:27:43 pasglop kernel: [ 41.509066] usb 4-1: reset full speed USB device using uhci_hcd and address 3
...
> > At the end, I think I yanked it out.
This looks a lot like a hardware problem, such as bad USB cables.
Could you collect a usbmon trace for bus 4? It ought to show whether
this is the case or whether software is at fault.
Alan Stern
On Fri, 9 Oct 2009, Alan Stern wrote:
> On Sat, 10 Oct 2009, Benjamin Herrenschmidt wrote:
>
> > (Adding Rafael)
> >
> > On Sat, 2009-10-10 at 11:31 +1100, Benjamin Herrenschmidt wrote:
> > > On Sat, 2009-10-10 at 11:25 +1100, Benjamin Herrenschmidt wrote:
> > > > Hi folks !
> > > >
> > > > My USB GSM modem (Huawei 169, pretty common stuff) stopped working in
> > > > the latest ubuntu karmic update. So far, I tracked it down to a
> > > > regression that happened in the stable releases between 2.6.31.1 and
> > > > 2.6.31.2 (still present in .3). I haven't tested 2.6.32-rc* yet and
> > > > haven't had a chance to bisect (need to make myself a trimmed
> > > > down .config first).
> This looks a lot like a hardware problem, such as bad USB cables.
> Could you collect a usbmon trace for bus 4? It ought to show whether
> this is the case or whether software is at fault.
If it's not a hardware issue and the modem really does work okay in
2.6.31.1, you should also collect a usbmon trace under that kernel for
comparison.
Alan Stern
On Fri, 2009-10-09 at 21:56 -0400, Alan Stern wrote:
> > > At the end, I think I yanked it out.
>
> This looks a lot like a hardware problem, such as bad USB cables.
> Could you collect a usbmon trace for bus 4? It ought to show whether
> this is the case or whether software is at fault.
It works just fine with 2.6.31.1
It's a USB modem "stick", no cables involved. Same symptom with another
stick from a co-worker. Both work fine on older kernels.
Cheers,
Ben.
On Fri, 2009-10-09 at 22:03 -0400, Alan Stern wrote:
> > This looks a lot like a hardware problem, such as bad USB cables.
> > Could you collect a usbmon trace for bus 4? It ought to show whether
> > this is the case or whether software is at fault.
>
> If it's not a hardware issue and the modem really does work okay in
> 2.6.31.1, you should also collect a usbmon trace under that kernel for
> comparison.
Ok. I'll give those a go later this week-end.
Cheers,
Ben.
On Fri, 2009-10-09 at 22:03 -0400, Alan Stern wrote:
> If it's not a hardware issue and the modem really does work okay in
> 2.6.31.1, you should also collect a usbmon trace under that kernel for
> comparison.
I put some logs at:
http://bugzilla.kernel.org/show_bug.cgi?id=14355
BTW. Do we have a nice GUI to browse these or it's time for me to work
on my pygtk skills ? :-)
Cheers,
Ben.
Benjamin Herrenschmidt schrieb:
> The symptom is that the USB modem just disconnects/reconnects in a loop.
> The log looks like what I pasted below when plugging the device (and
> leaving it in, the disconnects don't correspond to the device being
> removed).
This is one of the mode switching devices. It is switched to modem
mode by "usb_stor_huawei_e220_init".
Something keeps resetting it to initial mode. It might be a
powersave/suspend issue.
Josua Dietze
--
Man is the only creature on earth enabled to take a
warm meal while flying! Loriot
On Sat, 2009-10-10 at 09:38 +0200, Josua Dietze wrote:
> Benjamin Herrenschmidt schrieb:
>
>
> > The symptom is that the USB modem just disconnects/reconnects in a loop.
> > The log looks like what I pasted below when plugging the device (and
> > leaving it in, the disconnects don't correspond to the device being
> > removed).
>
>
> This is one of the mode switching devices. It is switched to modem
> mode by "usb_stor_huawei_e220_init".
>
> Something keeps resetting it to initial mode. It might be a
> powersave/suspend issue.
suspend is a good candidate yeah, autosuspend might be causing something
like that, I'll see what I can find. I didn't spot an obvious change to
the USB suspend policy between those two kernels, but it could be
trigged by one of the numerous changes that went into usb-serial.
Cheers,
Ben.
Am Samstag, 10. Oktober 2009 09:41:01 schrieb Benjamin Herrenschmidt:
> suspend is a good candidate yeah, autosuspend might be causing something
> like that, I'll see what I can find. I didn't spot an obvious change to
> the USB suspend policy between those two kernels, but it could be
> trigged by one of the numerous changes that went into usb-serial.
Then you can simply test this hunch by switching it off. If that helps
please recompile with CONFIG_USB_DEBUG enabled?
But I don't understand why the stable series is affected. Autosuspend
patches didn't go into it, did they Greg?
Regards
Oliver
On Sat, Oct 10, 2009 at 11:55:47AM +0200, Oliver Neukum wrote:
> Am Samstag, 10. Oktober 2009 09:41:01 schrieb Benjamin Herrenschmidt:
> > suspend is a good candidate yeah, autosuspend might be causing something
> > like that, I'll see what I can find. I didn't spot an obvious change to
> > the USB suspend policy between those two kernels, but it could be
> > trigged by one of the numerous changes that went into usb-serial.
>
> Then you can simply test this hunch by switching it off. If that helps
> please recompile with CONFIG_USB_DEBUG enabled?
>
> But I don't understand why the stable series is affected. Autosuspend
> patches didn't go into it, did they Greg?
Not that I can see, no.
thanks,
greg k-h
On Sat, 10 Oct 2009, Benjamin Herrenschmidt wrote:
> On Fri, 2009-10-09 at 22:03 -0400, Alan Stern wrote:
>
> > If it's not a hardware issue and the modem really does work okay in
> > 2.6.31.1, you should also collect a usbmon trace under that kernel for
> > comparison.
>
> I put some logs at:
>
> http://bugzilla.kernel.org/show_bug.cgi?id=14355
>
> BTW. Do we have a nice GUI to browse these or it's time for me to work
> on my pygtk skills ? :-)
I don't know of any GUI for browsing these trace files. On the other
hand I believe Wireshark is aware of usbmon's binary interface, so you
can use it to capture and browse packets. For email purposes, I find
the simple text interface easier to use.
Alan Stern
On Sat, 10 Oct 2009, Josua Dietze wrote:
> Benjamin Herrenschmidt schrieb:
>
>
> > The symptom is that the USB modem just disconnects/reconnects in a loop.
> > The log looks like what I pasted below when plugging the device (and
> > leaving it in, the disconnects don't correspond to the device being
> > removed).
>
>
> This is one of the mode switching devices. It is switched to modem
> mode by "usb_stor_huawei_e220_init".
>
> Something keeps resetting it to initial mode. It might be a
> powersave/suspend issue.
It's not related to powersave or suspend. (Although both trace files
show that the device's remote-wakeup feature did get enabled; I have no
idea what code was responsible for doing that. AFAIK it shouldn't
happen unless the device is about to be suspended.)
No, the problem is related to the mode-switching. In particular, the
2.6.31.3 log shows that the mass-storage interface got into trouble
because of a couple of bugs in the device. These bugs caused
usb-storage to issue a device reset, but after the reset the same thing
happened again and we entered an endless loop.
The reason this doesn't happen under 2.6.31.1 is explained by commit
b7c8b54df8c2a82757d8aab48aaac198a49e2ff9 (which in the upstream kernel
is commit d0defb855c8504c49b92bdc0203689ce9b4cf7ba). It allows
usb-storage to bind to the Huawei Datacard device, whereas before the
mode switch would occur with no binding.
Regardless, we have to figure out some way to work around the device's
bugs. In some detail, here's what happened:
The device presented two LUNs on the mass-storage interface. LUN 0 was
the emulated CDROM (named "Mass Storage") and LUN 1 was direct-access
(named "SD Storage"). LUN 0 appeared to work normally, although it
reported Not Ready, No Medium Present errors. LUN 1 did the same
thing, but in its response to the REQUEST SENSE command it set the
additional-sense-length byte to 0x12 instead of 0x0a, for no apparent
reason. This caused usb-storage to assume the device supported SANE
SENSE, which presumably it doesn't.
Further REQUEST SENSE commands therefore requested 96 bytes of data
instead of the standard 18 bytes. With LUN 0 this worked okay. But
with LUN 1 it didn't; the device reported a failure of the REQUEST
SENSE. This is what caused usb-storage to issue the device reset.
After the reset usb-storage continued to ask for 96 bytes of sense
data, and LUN 1 continued to fail the commands. Hence the repeated
resets.
Thus the two bugs in the Huawei device are: Incorrect
additional-sense-length byte for LUN 1, and incorrect CSW for a 96-byte
REQUEST SENSE on LUN 1.
I can see two approaches for working around this. The first is to make
the SENSE SENSE test more discriminating. For example, test for
additional-sense-length values larger than 0x12 instead of larger than
0x0a. Ben Efros, would this be acceptable?
The second approach is to add a SINGLE_LUN flag to all the Huawei
entries in unusual_devs.h. It's not clear that this is a good idea; if
one of those devices really does have an SD card then people might want
to be able to use it.
Alan Stern
On Saturday 10 October 2009 19:05:22 Alan Stern wrote:
> On Sat, 10 Oct 2009, Josua Dietze wrote:
> > Benjamin Herrenschmidt schrieb:
> > > The symptom is that the USB modem just disconnects/reconnects in a
> > > loop. The log looks like what I pasted below when plugging the device
> > > (and leaving it in, the disconnects don't correspond to the device
> > > being removed).
> >
> > This is one of the mode switching devices. It is switched to modem
> > mode by "usb_stor_huawei_e220_init".
> >
> > Something keeps resetting it to initial mode. It might be a
> > powersave/suspend issue.
>
> It's not related to powersave or suspend. (Although both trace files
> show that the device's remote-wakeup feature did get enabled; I have no
> idea what code was responsible for doing that. AFAIK it shouldn't
> happen unless the device is about to be suspended.)
>
> No, the problem is related to the mode-switching. In particular, the
> 2.6.31.3 log shows that the mass-storage interface got into trouble
> because of a couple of bugs in the device. These bugs caused
> usb-storage to issue a device reset, but after the reset the same thing
> happened again and we entered an endless loop.
>
> The reason this doesn't happen under 2.6.31.1 is explained by commit
> b7c8b54df8c2a82757d8aab48aaac198a49e2ff9 (which in the upstream kernel
> is commit d0defb855c8504c49b92bdc0203689ce9b4cf7ba). It allows
> usb-storage to bind to the Huawei Datacard device, whereas before the
> mode switch would occur with no binding.
>
> Regardless, we have to figure out some way to work around the device's
> bugs. In some detail, here's what happened:
>
> The device presented two LUNs on the mass-storage interface. LUN 0 was
> the emulated CDROM (named "Mass Storage") and LUN 1 was direct-access
> (named "SD Storage"). LUN 0 appeared to work normally, although it
> reported Not Ready, No Medium Present errors. LUN 1 did the same
> thing, but in its response to the REQUEST SENSE command it set the
> additional-sense-length byte to 0x12 instead of 0x0a, for no apparent
> reason. This caused usb-storage to assume the device supported SANE
> SENSE, which presumably it doesn't.
>
> Further REQUEST SENSE commands therefore requested 96 bytes of data
> instead of the standard 18 bytes. With LUN 0 this worked okay. But
> with LUN 1 it didn't; the device reported a failure of the REQUEST
> SENSE. This is what caused usb-storage to issue the device reset.
>
> After the reset usb-storage continued to ask for 96 bytes of sense
> data, and LUN 1 continued to fail the commands. Hence the repeated
> resets.
>
> Thus the two bugs in the Huawei device are: Incorrect
> additional-sense-length byte for LUN 1, and incorrect CSW for a 96-byte
> REQUEST SENSE on LUN 1.
>
> I can see two approaches for working around this. The first is to make
> the SENSE SENSE test more discriminating. For example, test for
> additional-sense-length values larger than 0x12 instead of larger than
> 0x0a. Ben Efros, would this be acceptable?
>
> The second approach is to add a SINGLE_LUN flag to all the Huawei
> entries in unusual_devs.h. It's not clear that this is a good idea; if
> one of those devices really does have an SD card then people might want
> to be able to use it.
No, this is not a good idea. Some of the devices have a MicroSD slot - like
Huawei E176. The bad thing is that E176 uses the same device ID as Huawei
E220 (and possibly some other devices too).
--
Ondrej Zary
On Sat, 10 Oct 2009, Alan Stern wrote:
> On Sat, 10 Oct 2009, Josua Dietze wrote:
...
> > This is one of the mode switching devices. It is switched to modem
> > mode by "usb_stor_huawei_e220_init".
> >
> > Something keeps resetting it to initial mode. It might be a
> > powersave/suspend issue.
>
> It's not related to powersave or suspend. (Although both trace files
> show that the device's remote-wakeup feature did get enabled; I have no
> idea what code was responsible for doing that. AFAIK it shouldn't
> happen unless the device is about to be suspended.)
It turns out that the remote-wakeup enable _is_ the mode-switch
command. Don't ask me why the manufacturer decided to use an
pre-existing command to tell the device to switch modes.
Anyway, it's clear from the logs that the mode switch worked in both
cases. Initially the device shows only one interface, and after the
mode switch it shows four.
Alan Stern
> The device presented two LUNs on the mass-storage interface. LUN 0 was
> the emulated CDROM (named "Mass Storage") and LUN 1 was direct-access
> (named "SD Storage"). LUN 0 appeared to work normally, although it
> reported Not Ready, No Medium Present errors. LUN 1 did the same
> thing, but in its response to the REQUEST SENSE command it set the
> additional-sense-length byte to 0x12 instead of 0x0a, for no apparent
> reason. This caused usb-storage to assume the device supported SANE
> SENSE, which presumably it doesn't.
Interesting. Under the windows, the device exposes a CD-ROM (which
contains windows SW for it). It also has an micro-SD connector as some
kind of "bonus" though I've never used it.
> Further REQUEST SENSE commands therefore requested 96 bytes of data
> instead of the standard 18 bytes. With LUN 0 this worked okay. But
> with LUN 1 it didn't; the device reported a failure of the REQUEST
> SENSE. This is what caused usb-storage to issue the device reset.
Might be interesting to see what happens with a micro-SD actually in the
slot. Also, doing a device-reset on a multi-function device because one
of the functions isn't too happy may be a tad harsh no ?
> After the reset usb-storage continued to ask for 96 bytes of sense
> data, and LUN 1 continued to fail the commands. Hence the repeated
> resets.
Ok.
> Thus the two bugs in the Huawei device are: Incorrect
> additional-sense-length byte for LUN 1, and incorrect CSW for a 96-byte
> REQUEST SENSE on LUN 1.
>
> I can see two approaches for working around this. The first is to make
> the SENSE SENSE test more discriminating. For example, test for
> additional-sense-length values larger than 0x12 instead of larger than
> 0x0a. Ben Efros, would this be acceptable?
>
> The second approach is to add a SINGLE_LUN flag to all the Huawei
> entries in unusual_devs.h. It's not clear that this is a good idea; if
> one of those devices really does have an SD card then people might want
> to be able to use it.
They do have an SD slot indeed.
Any pointer to the piece of code I can tweak to change 0xa to 0x12
(SENSE stuff) to see if that helps ?
Cheers,
Ben.
> Alan Stern
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-usb" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
On Sat, 2009-10-10 at 16:41 -0400, Alan Stern wrote:
> On Sat, 10 Oct 2009, Alan Stern wrote:
>
> > On Sat, 10 Oct 2009, Josua Dietze wrote:
> ...
> > > This is one of the mode switching devices. It is switched to modem
> > > mode by "usb_stor_huawei_e220_init".
> > >
> > > Something keeps resetting it to initial mode. It might be a
> > > powersave/suspend issue.
> >
> > It's not related to powersave or suspend. (Although both trace files
> > show that the device's remote-wakeup feature did get enabled; I have no
> > idea what code was responsible for doing that. AFAIK it shouldn't
> > happen unless the device is about to be suspended.)
>
> It turns out that the remote-wakeup enable _is_ the mode-switch
> command. Don't ask me why the manufacturer decided to use an
> pre-existing command to tell the device to switch modes.
>
> Anyway, it's clear from the logs that the mode switch worked in both
> cases. Initially the device shows only one interface, and after the
> mode switch it shows four.
Yes, that works, you can see the ttyUSBx ports showing up. It looks like
it may just be the resets coming from usb-storage that are breaking
things.
Cheers,
Ben.
> Further REQUEST SENSE commands therefore requested 96 bytes of data
> instead of the standard 18 bytes. With LUN 0 this worked okay. But
> with LUN 1 it didn't; the device reported a failure of the REQUEST
> SENSE. This is what caused usb-storage to issue the device reset.
>
> After the reset usb-storage continued to ask for 96 bytes of sense
> data, and LUN 1 continued to fail the commands. Hence the repeated
> resets.
Maybe a better approach would be to go back to 18 bytes when it fails,
what do you think ?
Ben.
On Sun, 2009-10-11 at 08:20 +1100, Benjamin Herrenschmidt wrote:
> Yes, that works, you can see the ttyUSBx ports showing up. It looks like
> it may just be the resets coming from usb-storage that are breaking
> things.
Ok so I did a quick hack to usb-storage, basically put the block that
tests for the response size and sets USB_FL_SANE_SENSE into an #if 0 :
(This is 2.6.31.2 since that's what I have a built source at hand
right now)
#if 0
/* If the sense data returned is larger than 18-bytes then we
* assume this device supports requesting more in the future.
* The response code must be 70h through 73h inclusive.
*/
if (srb->sense_buffer[7] > (US_SENSE_SIZE - 8) &&
!(us->fflags & US_FL_SANE_SENSE) &&
(srb->sense_buffer[0] & 0x7C) == 0x70) {
US_DEBUGP("-- SANE_SENSE support enabled\n");
us->fflags |= US_FL_SANE_SENSE;
/* Indicate to the user that we truncated their sense
* because we didn't know it supported larger sense.
*/
US_DEBUGP("-- Sense data truncated to %i from %i\n",
US_SENSE_SIZE,
srb->sense_buffer[7] + 8);
srb->sense_buffer[7] = (US_SENSE_SIZE - 8);
}
#endif
Now, the result in the dmesg log is :
Oct 11 09:04:05 pasglop kernel: [ 52.916100] usb 4-1: new full speed USB device using uhci_hcd and address 2
Oct 11 09:04:05 pasglop kernel: [ 53.076402] usb 4-1: configuration #1 chosen from 1 choice
Oct 11 09:04:06 pasglop kernel: [ 53.104090] Initializing USB Mass Storage driver...
Oct 11 09:04:06 pasglop kernel: [ 53.105405] scsi2 : SCSI emulation for USB Mass Storage devices
Oct 11 09:04:06 pasglop kernel: [ 53.105585] usbcore: registered new interface driver usb-storage
Oct 11 09:04:06 pasglop kernel: [ 53.105589] USB Mass Storage support registered.
Oct 11 09:04:06 pasglop kernel: [ 53.107164] usb-storage: device found at 2
Oct 11 09:04:06 pasglop kernel: [ 53.107167] usb-storage: waiting for device to settle before scanning
Oct 11 09:04:06 pasglop kernel: [ 53.224104] usb 4-1: USB disconnect, address 2
Oct 11 09:04:06 pasglop kernel: [ 53.960100] usb 4-1: new full speed USB device using uhci_hcd and address 3
Oct 11 09:04:11 pasglop kernel: [ 54.121941] usb 4-1: configuration #1 chosen from 1 choice
Oct 11 09:04:11 pasglop kernel: [ 54.140861] scsi6 : SCSI emulation for USB Mass Storage devices
Oct 11 09:04:11 pasglop kernel: [ 54.143007] usb-storage: device found at 3
Oct 11 09:04:11 pasglop kernel: [ 54.143010] usb-storage: waiting for device to settle before scanning
Oct 11 09:04:11 pasglop kernel: [ 59.141422] usb-storage: device scan complete
Oct 11 09:04:11 pasglop kernel: [ 59.144370] scsi 6:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
Oct 11 09:04:11 pasglop kernel: [ 59.147379] scsi 6:0:0:1: Direct-Access HUAWEI SD Storage 2.31 PQ: 0 ANSI: 2
Oct 11 09:04:11 pasglop kernel: [ 59.169383] sr1: scsi-1 drive
At which point nothing happens for a while (and no serial stuff shows up).
If I yank the device, I then see:
Oct 11 09:05:28 pasglop kernel: [ 59.169494] sr 6:0:0:0: Attached scsi CD-ROM sr1
Oct 11 09:05:28 pasglop kernel: [ 59.169563] sr 6:0:0:0: Attached scsi generic sg2 type 5
Oct 11 09:05:28 pasglop kernel: [ 59.169668] sd 6:0:0:1: Attached scsi generic sg3 type 0
Oct 11 09:05:28 pasglop kernel: [ 59.227809] sd 6:0:0:1: [sdb] Attached SCSI removable disk
Oct 11 09:05:28 pasglop kernel: [ 71.048322] ISO 9660 Extensions: Microsoft Joliet Level 1
Oct 11 09:05:28 pasglop kernel: [ 71.057316] ISOFS: changing to secondary root
Oct 11 09:05:28 pasglop kernel: [ 128.369159] usb 4-1: USB disconnect, address 3
Oct 11 09:05:28 pasglop kernel: [ 128.429675] scsi 6:0:0:0: rejecting I/O to dead device
However, if I put it back in later on ... it works. The storage shows up
and the modem too.
Weird. I'll have to reboot to try to reproduce with usbmon logging.
Cheers,
Ben.
On Sun, 11 Oct 2009, Benjamin Herrenschmidt wrote:
>
> > Further REQUEST SENSE commands therefore requested 96 bytes of data
> > instead of the standard 18 bytes. With LUN 0 this worked okay. But
> > with LUN 1 it didn't; the device reported a failure of the REQUEST
> > SENSE. This is what caused usb-storage to issue the device reset.
> >
> > After the reset usb-storage continued to ask for 96 bytes of sense
> > data, and LUN 1 continued to fail the commands. Hence the repeated
> > resets.
>
> Maybe a better approach would be to go back to 18 bytes when it fails,
> what do you think ?
We certainly could do that. But should we turn off the SANE_SENSE flag
at the same time?
Alan Stern
On Sat, 2009-10-10 at 18:52 -0400, Alan Stern wrote:
> > Maybe a better approach would be to go back to 18 bytes when it fails,
> > what do you think ?
>
> We certainly could do that. But should we turn off the SANE_SENSE flag
> at the same time?
I would think so, and not set it back the next time the sense buffer
claims more data in it (something like setting a NOT_REALLY_SANE_SENSE
flag ? :-)
Or not care and always do double sense on those devices. Whatever
works. It's not that sense was a fast path.
Cheers,
Ben.
On Sun, 2009-10-11 at 10:26 +1100, Benjamin Herrenschmidt wrote:
> On Sat, 2009-10-10 at 18:52 -0400, Alan Stern wrote:
> > > Maybe a better approach would be to go back to 18 bytes when it fails,
> > > what do you think ?
> >
> > We certainly could do that. But should we turn off the SANE_SENSE flag
> > at the same time?
>
> I would think so, and not set it back the next time the sense buffer
> claims more data in it (something like setting a NOT_REALLY_SANE_SENSE
> flag ? :-)
>
> Or not care and always do double sense on those devices. Whatever
> works. It's not that sense was a fast path.
Ok, so here's an absolutely horrible hack that makes it work here,
but of course, I think that should be done more cleanly.
With some printk added I verified that it does ping pong
US_FL_SANE_SENSE (ie, sets it back as soon as the command
succeeds) but I don't see that as a big deal though.
I doubt you want to apply that as-is though but in case you do:
Signed-off-by: Benjamin Herrenschmidt <[email protected]>
Cheers,
Ben.
--- a/drivers/usb/storage/transport.c 2009-10-09 14:34:14.638445171 +1100
+++ b/drivers/usb/storage/transport.c 2009-10-11 10:40:55.890868361 +1100
@@ -687,6 +687,7 @@
US_DEBUGP("-- unexpectedly short transfer\n");
}
+ Retry_Sense:
/* Now, if we need to do the auto-sense, let's do it */
if (need_auto_sense) {
int temp_result;
@@ -722,6 +723,11 @@
}
if (temp_result != USB_STOR_TRANSPORT_GOOD) {
US_DEBUGP("-- auto-sense failure\n");
+ if (us->fflags & US_FL_SANE_SENSE) {
+ us->fflags &= ~US_FL_SANE_SENSE;
+ US_DEBUGP("-- retry without SANE_SENSE\n");
+ goto Retry_Sense;
+ }
/* we skip the reset if this happens to be a
* multi-target device, since failure of an
----- "Alan Stern" <[email protected]> wrote:
> The device presented two LUNs on the mass-storage interface. LUN 0
> was
> the emulated CDROM (named "Mass Storage") and LUN 1 was direct-access
>
> (named "SD Storage"). LUN 0 appeared to work normally, although it
> reported Not Ready, No Medium Present errors. LUN 1 did the same
> thing, but in its response to the REQUEST SENSE command it set the
> additional-sense-length byte to 0x12 instead of 0x0a, for no apparent
> reason. This caused usb-storage to assume the device supported SANE
> SENSE, which presumably it doesn't.
>
<SNIP>
>
> Thus the two bugs in the Huawei device are: Incorrect
> additional-sense-length byte for LUN 1, and incorrect CSW for a
> 96-byte
> REQUEST SENSE on LUN 1.
>
> I can see two approaches for working around this. The first is to
> make
> the SENSE SENSE test more discriminating. For example, test for
> additional-sense-length values larger than 0x12 instead of larger
> than
> 0x0a. Ben Efros, would this be acceptable?
>
> The second approach is to add a SINGLE_LUN flag to all the Huawei
> entries in unusual_devs.h. It's not clear that this is a good idea; if
> one of those devices really does have an SD card then people might want
> to be able to use it.
Most SAT devices will never set an additional sense length value higher than 0x0e on the Descriptor Format Sense Data when returning an ATA Return Descriptor. I'd prefer not to arbitrarily set the range check to be > 0x12 for SANE_SENSE to kick in. If that is the ultimate solution, then I'd rather see the whole SANE_SENSE detection if-block removed in its entirely. I really don't think that will be necessary.
Both proposed solutions seem to have their drawbacks. Maybe its time to start noting buggy devices that are known to be "insane" in regards to sense data. If the device has usb flag "INSANE_SENSE" then we'll never ever set SANE_SENSE.
Ben Herrenschmidt's patch[1] to retry without SANE_SENSE might be combined be able to be used to detect this 'INSANE_SENSE' scenario, but not in its current form.
Devices lying about the "additional sense length" doesn't seem all that common, so it might be better to just flag the device as insane and not worry about reworking Ben Herrenschmidt's patch.
[1] http://lkml.org/lkml/2009/10/10/211
On Sat, 2009-10-10 at 17:21 -0700, Ben Efros wrote:
>
> Ben Herrenschmidt's patch[1] to retry without SANE_SENSE might be
> combined be able to be used to detect this 'INSANE_SENSE' scenario,
> but not in its current form.
>
> Devices lying about the "additional sense length" doesn't seem all
> that common, so it might be better to just flag the device as insane
> and not worry about reworking Ben Herrenschmidt's patch.
I don't like flagging devices ... though we already somewhat do it for
the mode switch so it would be possible to stick the flag there.
Another option is to set the insane flag from a retry path similar
to what I posted so that it doesn't ping pong.
In any case, a decision should be made soon as current -stable is broken
and these devices are very common.
Cheers,
Ben.
On Sun, 11 Oct 2009, Benjamin Herrenschmidt wrote:
> On Sun, 2009-10-11 at 08:20 +1100, Benjamin Herrenschmidt wrote:
>
> > Yes, that works, you can see the ttyUSBx ports showing up. It looks like
> > it may just be the resets coming from usb-storage that are breaking
> > things.
>
> Ok so I did a quick hack to usb-storage, basically put the block that
> tests for the response size and sets USB_FL_SANE_SENSE into an #if 0 :
> Now, the result in the dmesg log is :
>
> Oct 11 09:04:05 pasglop kernel: [ 52.916100] usb 4-1: new full speed USB device using uhci_hcd and address 2
> Oct 11 09:04:05 pasglop kernel: [ 53.076402] usb 4-1: configuration #1 chosen from 1 choice
> Oct 11 09:04:06 pasglop kernel: [ 53.104090] Initializing USB Mass Storage driver...
> Oct 11 09:04:06 pasglop kernel: [ 53.105405] scsi2 : SCSI emulation for USB Mass Storage devices
> Oct 11 09:04:06 pasglop kernel: [ 53.105585] usbcore: registered new interface driver usb-storage
> Oct 11 09:04:06 pasglop kernel: [ 53.105589] USB Mass Storage support registered.
> Oct 11 09:04:06 pasglop kernel: [ 53.107164] usb-storage: device found at 2
> Oct 11 09:04:06 pasglop kernel: [ 53.107167] usb-storage: waiting for device to settle before scanning
> Oct 11 09:04:06 pasglop kernel: [ 53.224104] usb 4-1: USB disconnect, address 2
> Oct 11 09:04:06 pasglop kernel: [ 53.960100] usb 4-1: new full speed USB device using uhci_hcd and address 3
> Oct 11 09:04:11 pasglop kernel: [ 54.121941] usb 4-1: configuration #1 chosen from 1 choice
> Oct 11 09:04:11 pasglop kernel: [ 54.140861] scsi6 : SCSI emulation for USB Mass Storage devices
> Oct 11 09:04:11 pasglop kernel: [ 54.143007] usb-storage: device found at 3
> Oct 11 09:04:11 pasglop kernel: [ 54.143010] usb-storage: waiting for device to settle before scanning
> Oct 11 09:04:11 pasglop kernel: [ 59.141422] usb-storage: device scan complete
> Oct 11 09:04:11 pasglop kernel: [ 59.144370] scsi 6:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
> Oct 11 09:04:11 pasglop kernel: [ 59.147379] scsi 6:0:0:1: Direct-Access HUAWEI SD Storage 2.31 PQ: 0 ANSI: 2
> Oct 11 09:04:11 pasglop kernel: [ 59.169383] sr1: scsi-1 drive
>
> At which point nothing happens for a while (and no serial stuff shows up).
>
> If I yank the device, I then see:
>
> Oct 11 09:05:28 pasglop kernel: [ 59.169494] sr 6:0:0:0: Attached scsi CD-ROM sr1
> Oct 11 09:05:28 pasglop kernel: [ 59.169563] sr 6:0:0:0: Attached scsi generic sg2 type 5
> Oct 11 09:05:28 pasglop kernel: [ 59.169668] sd 6:0:0:1: Attached scsi generic sg3 type 0
> Oct 11 09:05:28 pasglop kernel: [ 59.227809] sd 6:0:0:1: [sdb] Attached SCSI removable disk
> Oct 11 09:05:28 pasglop kernel: [ 71.048322] ISO 9660 Extensions: Microsoft Joliet Level 1
> Oct 11 09:05:28 pasglop kernel: [ 71.057316] ISOFS: changing to secondary root
> Oct 11 09:05:28 pasglop kernel: [ 128.369159] usb 4-1: USB disconnect, address 3
> Oct 11 09:05:28 pasglop kernel: [ 128.429675] scsi 6:0:0:0: rejecting I/O to dead device
The printk timestamps indicate that the first four lines above happened
before you unplugged the device. Maybe the first six. But evidently
the syslogd process was blocked.
>
> However, if I put it back in later on ... it works. The storage shows up
> and the modem too.
>
> Weird. I'll have to reboot to try to reproduce with usbmon logging.
You might have to get a stack trace (Alt-SysRq-T) as well. It sounds
like something important got hung up somewhere. Perhaps the usb-serial
modules couldn't be loaded for that reason.
Alan Stern