usb connect problems

Bug #231049 reported by jtclicker on 2008-05-16
36
This bug affects 3 people
Affects Status Importance Assigned to Milestone
NULL Project
Undecided
Unassigned
linux (Ubuntu)
Undecided
Unassigned
Declined for Intrepid by Jeremy Foshee

Bug Description

Hardy won't mount 'see' or charge my sandisk clip mp3 player since upgrade from Gutsy. Works in boht gutsy and windows

59.683231] usb 5-8: new high speed USB device using ehci_hcd and address 4
[ 63.153322] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[ 63.153331] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 64.097768] eth0: no IPv6 routers present
[ 98.516043] usb 5-8: new high speed USB device using ehci_hcd and address 5
[ 101.846418] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[ 101.846427] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 247.536810] usb 5-7: new high speed USB device using ehci_hcd and address 6
[ 247.729912] ehci_hcd 0000:00:1d.7: port 7 reset error -110
[ 247.729920] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 370.301819] usb 5-7: new high speed USB device using ehci_hcd and address 7
[ 370.808733] usb 5-7: new high speed USB device using ehci_hcd and address 8
[ 370.954228] usb 5-7: configuration #1 chosen from 1 choice
[ 370.982121] scsi5 : SCSI emulation for USB Mass Storage devices
[ 370.988384] usb-storage: device found at 8
[ 370.988390] usb-storage: waiting for device to settle before scanning
[ 375.979541] usb-storage: device scan complete
[ 375.980665] scsi 5:0:0:0: Direct-Access SanDisk Sansa Clip 2GB v01. PQ: 0 ANSI: 0
[ 375.992629] sd 5:0:0:0: [sdd] 3992576 512-byte hardware sectors (2044 MB)
[ 376.000243] sd 5:0:0:0: [sdd] Write Protect is off
[ 376.000249] sd 5:0:0:0: [sdd] Mode Sense: 04 00 00 00
[ 376.000251] sd 5:0:0:0: [sdd] Assuming drive cache: write through
[ 376.002842] sd 5:0:0:0: [sdd] 3992576 512-byte hardware sectors (2044 MB)
[ 376.003721] sd 5:0:0:0: [sdd] Write Protect is off
[ 376.003726] sd 5:0:0:0: [sdd] Mode Sense: 04 00 00 00
[ 376.003728] sd 5:0:0:0: [sdd] Assuming drive cache: write through
[ 376.003734] sdd: unknown partition table
[ 376.010371] sd 5:0:0:0: [sdd] Attached SCSI removable disk
[ 376.010420] sd 5:0:0:0: Attached scsi generic sg5 type 0
[ 378.601804] scsi 5:0:0:0: rejecting I/O to dead device
[ 388.650573] usb 5-7: reset high speed USB device using ehci_hcd and address 8
[ 623.607185] usb 5-7: reset high speed USB device using ehci_hcd and address 8
[ 930.150523] usb 5-7: USB disconnect, address 8
[ 963.319459] usb 5-8: new high speed USB device using ehci_hcd and address 9
[ 966.586364] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[ 966.586373] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 1005.580914] usb 5-8: new high speed USB device using ehci_hcd and address 10
[ 1008.873872] usb 5-8: device descriptor read/64, error -71
[ 1068.546042] usb 5-8: new high speed USB device using ehci_hcd and address 11
[ 1071.868432] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[ 1071.868441] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 1244.101951] usb 5-8: new high speed USB device using ehci_hcd and address 12
[ 1247.603956] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[ 1247.603965] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 3429.404556] usb 5-7: new high speed USB device using ehci_hcd and address 13
[ 3432.790809] ehci_hcd 0000:00:1d.7: port 7 reset error -110
[ 3432.790817] hub 5-0:1.0: hub_port_status failed (err = -32)
[ 9281.384346] usb 5-8: new high speed USB device using ehci_hcd and address 14
[ 9284.786566] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[ 9284.786575] hub 5-0:1.0: hub_port_status failed (err = -32)
[13405.637287] usb 5-8: new high speed USB device using ehci_hcd and address 15
[13408.991610] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[13408.991619] hub 5-0:1.0: hub_port_status failed (err = -32)
[50827.571346] usb 5-8: new high speed USB device using ehci_hcd and address 16
[50830.961590] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[50830.961600] hub 5-0:1.0: hub_port_status failed (err = -32)
[50838.471989] usb 5-8: new high speed USB device using ehci_hcd and address 17
[50838.625734] usb 5-8: configuration #1 chosen from 1 choice
[50838.654576] scsi6 : SCSI emulation for USB Mass Storage devices
[50838.655927] usb-storage: device found at 17
[50838.655932] usb-storage: waiting for device to settle before scanning
[50838.727783] usb 5-8: USB disconnect, address 17
[50838.970923] usb 5-8: new high speed USB device using ehci_hcd and address 18
[50839.124976] usb 5-8: configuration #1 chosen from 1 choice
[50839.131580] scsi7 : SCSI emulation for USB Mass Storage devices
[50839.132065] usb-storage: device found at 18
[50839.132070] usb-storage: waiting for device to settle before scanning
[50840.319529] usb 5-8: USB disconnect, address 18
[50841.349820] usb 5-8: new high speed USB device using ehci_hcd and address 19
[50841.492430] usb 5-8: configuration #1 chosen from 1 choice
[50841.525460] scsi8 : SCSI emulation for USB Mass Storage devices
[50841.529508] usb-storage: device found at 19
[50841.529513] usb-storage: waiting for device to settle before scanning
[50844.280239] usb 5-8: USB disconnect, address 19
[50848.135283] usb 5-8: new high speed USB device using ehci_hcd and address 20
[50848.281189] usb 5-8: configuration #1 chosen from 1 choice
[50848.309240] scsi9 : SCSI emulation for USB Mass Storage devices
[50848.314938] usb-storage: device found at 20
[50848.314943] usb-storage: waiting for device to settle before scanning
[50853.305508] usb-storage: device scan complete
[50853.306635] scsi 9:0:0:0: Direct-Access SanDisk Sansa Clip 2GB v01. PQ: 0 ANSI: 0
[50853.318838] sd 9:0:0:0: [sdd] 3992576 512-byte hardware sectors (2044 MB)
[50853.319483] sd 9:0:0:0: [sdd] Write Protect is off
[50853.319488] sd 9:0:0:0: [sdd] Mode Sense: 04 00 00 00
[50853.319491] sd 9:0:0:0: [sdd] Assuming drive cache: write through
[50853.322079] sd 9:0:0:0: [sdd] 3992576 512-byte hardware sectors (2044 MB)
[50853.322955] sd 9:0:0:0: [sdd] Write Protect is off
[50853.322960] sd 9:0:0:0: [sdd] Mode Sense: 04 00 00 00
[50853.322963] sd 9:0:0:0: [sdd] Assuming drive cache: write through
[50853.322968] sdd:
[50853.325734] sd 9:0:0:0: [sdd] Attached SCSI removable disk
[50853.325785] sd 9:0:0:0: Attached scsi generic sg5 type 0
[50855.405324] scsi 9:0:0:0: rejecting I/O to dead device
[50855.479573] usb 5-8: reset high speed USB device using ehci_hcd and address 20
[50866.436455] usb 5-8: USB disconnect, address 20
[50867.270310] usb 5-8: new high speed USB device using ehci_hcd and address 21
[50869.479073] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[50869.479083] hub 5-0:1.0: hub_port_status failed (err = -32)
[50895.441945] usb 5-8: new high speed USB device using ehci_hcd and address 22
[50895.770753] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[50895.770762] hub 5-0:1.0: hub_port_status failed (err = -32)
[50939.774972] usb 5-8: new high speed USB device using ehci_hcd and address 23
[50940.083820] ehci_hcd 0000:00:1d.7: port 8 reset error -110
[50940.083828] hub 5-0:1.0: hub_port_status failed (err = -32)
[51048.797422] usb 5-7: new high speed USB device using ehci_hcd and address 24
[51048.986525] ehci_hcd 0000:00:1d.7: port 7 reset error -110

foulbeast (knickell) wrote :

I am having the exact same issue shown above.

More details are here: http://ubuntuforums.org/showthread.php?t=790517&highlight=sansa+clip

ibizatunes (ibizatunes) wrote :
Download full text (27.5 KiB)

[ 12.829854] MEM window: efc00000-efcfffff
[ 12.829858] PREFETCH window: disabled.
[ 12.829863] PCI: Bridge: 0000:00:1e.0
[ 12.829866] IO window: c000-cfff
[ 12.829871] MEM window: efb00000-efbfffff
[ 12.829875] PREFETCH window: disabled.
[ 12.829894] ACPI: PCI Interrupt 0000:00:01.0[A] -> GSI 16 (level, low) -> IRQ 16
[ 12.829900] PCI: Setting latency timer of device 0000:00:01.0 to 64
[ 12.829919] ACPI: PCI Interrupt 0000:00:1c.0[A] -> GSI 16 (level, low) -> IRQ 16
[ 12.829924] PCI: Setting latency timer of device 0000:00:1c.0 to 64
[ 12.829936] PCI: Setting latency timer of device 0000:00:1e.0 to 64
[ 12.829947] NET: Registered protocol family 2
[ 12.867122] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 12.867422] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[ 12.867997] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[ 12.868286] TCP: Hash tables configured (established 131072 bind 65536)
[ 12.868289] TCP reno registered
[ 12.879201] checking if image is initramfs... it is
[ 13.495106] Freeing initrd memory: 7704k freed
[ 13.495263] Simple Boot Flag at 0x7a set to 0x1
[ 13.495777] audit: initializing netlink socket (disabled)
[ 13.495791] audit(1211571081.020:1): initialized
[ 13.496003] highmem bounce pool size: 64 pages
[ 13.498412] VFS: Disk quotas dquot_6.5.1
[ 13.498501] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 13.498656] io scheduler noop registered
[ 13.498658] io scheduler anticipatory registered
[ 13.498660] io scheduler deadline registered
[ 13.498672] io scheduler cfq registered (default)
[ 13.498770] Boot video device is 0000:01:00.0
[ 13.498778] PCI: Firmware left 0000:03:08.0 e100 interrupts enabled, disabling
[ 13.498918] PCI: Setting latency timer of device 0000:00:01.0 to 64
[ 13.498960] assign_interrupt_mode Found MSI capability
[ 13.498997] Allocate Port Service[0000:00:01.0:pcie00]
[ 13.499091] PCI: Setting latency timer of device 0000:00:1c.0 to 64
[ 13.499137] assign_interrupt_mode Found MSI capability
[ 13.499174] Allocate Port Service[0000:00:1c.0:pcie00]
[ 13.499217] Allocate Port Service[0000:00:1c.0:pcie02]
[ 13.499539] isapnp: Scanning for PnP cards...
[ 13.851325] isapnp: No Plug & Play device found
[ 13.888639] Real Time Clock Driver v1.12ac
[ 13.888750] Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
[ 13.890173] RAMDISK driver initialized: 16 RAM disks of 65536K size 1024 blocksize
[ 13.890254] input: Macintosh mouse button emulation as /devices/virtual/input/input0
[ 13.890437] PNP: No PS/2 controller found. Probing ports directly.
[ 13.892997] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 13.893004] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 13.910634] mice: PS/2 mouse device common for all mice
[ 13.910786] EISA: Probing bus 0 at eisa.0
[ 13.910790] EISA: Cannot allocate resource for mainboard
[ 13.910797] Cannot allocate resource for EISA slot 2
[ 13.910820] EISA: Detected 0 cards.
[ 13.910823] cpuidle: using governor ladder
[ 13.910826] cpuidle: using governor menu
[ 13.910909] NET: Re...

ibizatunes (ibizatunes) wrote :

for me this wasnt a bug, i had a faulty cable,

jtclicker (lists-ya) wrote :

If you look at the output listed, Hardy 'sees' the device and then
disconnects it. Works with the same cable in Gutsy and Wndows

Robert (robrwo) wrote :

I'm having different USB problems on Hardy.

On a fresh boot, there are no problems. But when I resume from hibernation: some USB ports do not work well.

When I connect to one of my USB ports (on the left side of my ThinkPad), devices seem to connect with no problems. But when I connect to either of the other two USB ports (on the right side of my laptop), USB drives and phones takes an extremely long time (up to a few minutes) before showing up. A USB mouse never works. `lsusb` seems to crash if devices are connected to either of these ports.

Evan Rotert (evan-rotert) wrote :

I got a similar error message with my Sandisk Sansa Fuze MP3 player. I found a solution here:

https://answers.launchpad.net/ubuntu/+question/4272

Try 'sudo modprobe -r ehci_hcd'

It worked for me; now my mp3 player is detected normally. BTW, I'm running Hardy Heron fully updated as of today, 6/26/08.

Hope this helps!

David Ward (dpward) wrote :

I also have a Sandisk Sansa Fuze and am receiving the same error with Hardy:

[ 283.344161] usb 4-3: new high speed USB device using ehci_hcd and address 3
[ 285.017541] ehci_hcd 0000:00:1d.7: port 3 reset error -110
[ 285.017558] hub 4-0:1.0: hub_port_status failed (err = -32)

Just as Evan reported, disabling the ehci_hcd module does work around the issue:

[ 1124.379310] usb 2-1: new full speed USB device using uhci_hcd and address 2
[ 1125.255162] usb 2-1: new full speed USB device using uhci_hcd and address 3
[ 1125.432269] usb 2-1: configuration #1 chosen from 1 choice

Unfortunately this causes the device to operate in USB 1.1 mode with much slower transfer rates.

My goal here is to actually use the device in a Windows virtual machine running inside Hardy. However, Hardy needs to be able to add the USB device properly before the VM can use it. The VM does recognize the device after I disable ehci_hcd in Hardy, but otherwise it does not.

Peter Cherriman (pjcherriman) wrote :

I have the same problem with a sansa clip. In gutsy on my old computer it mounted ok but only ever at USB 1.1 speeds.

On my new Dell inspiron 530 in fails to mount 95% of the time with:

[ 105.895973] usb 8-3: new high speed USB device using ehci_hcd and address 2
[ 110.517165] ehci_hcd 0000:00:1d.7: port 3 reset error -110
[ 110.517177] hub 8-0:1.0: hub_port_status failed (err = -32)

Sometime after a few minutes (in 5% of cases) it mounts at USB2 (480) speeds, as shown by right-clicking on desktop icons and selecting properties and disk.

If I remove the ehci_hcd module with modprobe -r ehci_hcd, and then reload the module, it immediately mounts the device at USB2 speeds.

However if I unmount, and unplug the device, and then plug it back in, it fails to mount with the -110, -32 errors as before.

So I'm not sure if its some race condition with the uhci_hcd module, or a dodgy usb implementation in the device. I have noticed it doesn't take any notice of eject commands like my old mp3 player.

Its a real shame its such a hassle since its a nice mp3 player than is one of the few that can play ogg vorbis files also.

Peter Cherriman (pjcherriman) wrote :

Further update, and I have similar problems on the same dell machine running, the current lenny version of debian which has a newer kernel.

But back to hardy.

As noted in the ubuntu forum thread, running the lsusb command sometimes gets the device detected. Sometimes once is not enough though. Basically I get the -110, -32 errors, then after running lsusb a few times the device mounts at usb2 speeds, without the need to modprobe the module out and in.

So maybe it is a dodgy usb implementation, my sansa is running the current newer 1.29 firmware (the one that added ogg vorbis support) and is connected in MSC mode. Which strangely has a different usb device_id to when connected in auto mode!

Jaime Carpenter (j.carpenter) wrote :

I'm having the same problem with my Sansa Clip 2gig not being mounted. I get the same error:
hub 8-0:1.0: hub_port_status failed (err = -32)
Sansa version v01.01.18a
I have tried in MSC mode and Auto mode.

Andreas Moog (ampelbein) wrote :

Thank you for taking the time to report this bug and helping to make Ubuntu better. Can you try with intrepid live-cd to see if the issue is fixed there? Also, please include the information requested at https://help.ubuntu.com/community/DebuggingUSBStorage in your report.

Peter Cherriman (pjcherriman) wrote :

A further update, lsusb doesn't alway kick the usb device into life. The only sure way seems to be to unload the ehci_hcd module (and reload it if you want USB2 speeds)

I've since install a 2.6.27 kernel from https://launchpad.net/~kernel-ppa/+archive on my ubuntu hardy machine. I'm not sure how similar to the intrepid live-cd version this is. The packages I installed was

linux-image-2.6.27-3-generic_2.6.27-3.4_i386.deb

It then does much like it did under lenny, ie the USB device mounts automatically but only at USB1 speeds.

When the USB device is plugged in I get the following error messages:

[ 81.584040] usb 8-3: new high speed USB device using ehci_hcd and address 2
[ 86.717374] ehci_hcd 0000:00:1d.7: port 3 reset error -110
[ 86.717393] hub 8-0:1.0: hub_port_status failed (err = -32)
[ 86.920042] hub 8-0:1.0: unable to enumerate USB device on port 3
[ 87.176032] usb 5-1: new full speed USB device using uhci_hcd and address 2
[ 87.101504] usb 5-1: not running at top speed; connect to a high speed hub
[ 87.312008] usb 5-1: configuration #1 chosen from 1 choice

then it mounts but as a USB1 device (slow transfers)

However unloading and immediately reloading the ehci_hcd module:

sudo modprobe -r ehci_hcd; sudo modprobe ehci_hcd

gets it to remount as a USB2 device (fast transfers)

So I'm still thinking its a problem with the USB implementation in the device or the motherboard.

Peter Cherriman (pjcherriman) wrote :

The unloading and reloading of the ehci_hcd module gave me an idea. Does the ehci_hcd do something different when the device is plugged in, than from when it starts up.

I found that by booting (standard hardy 2.6.24 generic kernel) with the sansa clip plugged in. The sansa mounts automatically at USB2 speeds.

So there must be something different in the connect procedure when echi_hcd module loads, and connect procedure when a device is plugged in after the module has started. The difference in the procedure, is probably different to what windows does, and the sansa doesn't like it. I've no idea what the problem is though.

jtclicker (lists-ya) wrote :
Download full text (37.2 KiB)

Intrepid fixed the problem for me
dmesg

 61)
[ 0.000000] ACPI: BOOT 000FD2DE, 0028 (r1 DELL 8300 7 ASL 61)
[ 0.000000] ACPI: PM-Timer IO Port: 0x808
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
[ 0.000000] Processor #0 15:2 APIC version 20
[ 0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x01] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x03] disabled)
[ 0.000000] ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
[ 0.000000] IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.000000] ACPI: IRQ0 used by override.
[ 0.000000] ACPI: IRQ2 used by override.
[ 0.000000] ACPI: IRQ9 used by override.
[ 0.000000] Enabling APIC mode: Flat. Using 1 I/O APICs
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] Allocating PCI resources starting at 50000000 (gap: 40000000:bec00000)
[ 0.000000] swsusp: Registered nosave memory region: 00000000000a0000 - 00000000000f0000
[ 0.000000] swsusp: Registered nosave memory region: 00000000000f0000 - 0000000000100000
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 259958
[ 0.000000] Kernel command line: root=UUID=5dbf866b-9eb7-4033-8502-391b30e9476a ro quiet splash vga=795
[ 0.000000] mapped APIC to ffffb000 (fee00000)
[ 0.000000] mapped IOAPIC to ffffa000 (fec00000)
[ 0.000000] Enabling fast FPU save and restore... done.
[ 0.000000] Enabling unmasked SIMD FPU exception support... done.
[ 0.000000] Initializing CPU#0
[ 0.000000] PID hash table entries: 4096 (order: 12, 16384 bytes)
[ 0.000000] Detected 2593.515 MHz processor.
[ 9.960103] Console: colour dummy device 80x25
[ 9.960107] console [tty0] enabled
[ 9.960464] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 9.960864] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 9.990865] Memory: 1026500k/1048016k available (2177k kernel code, 20860k reserved, 1006k data, 368k init, 130512k highmem)
[ 9.990875] virtual kernel memory layout:
[ 9.990877] fixmap : 0xfff4b000 - 0xfffff000 ( 720 kB)
[ 9.990878] pkmap : 0xff800000 - 0xffc00000 (4096 kB)
[ 9.990879] vmalloc : 0xf8800000 - 0xff7fe000 ( 111 MB)
[ 9.990880] lowmem : 0xc0000000 - 0xf8000000 ( 896 MB)
[ 9.990881] .init : 0xc0421000 - 0xc047d000 ( 368 kB)
[ 9.990882] .data : 0xc0320514 - 0xc041bdc4 (1006 kB)
[ 9.990883] .text : 0xc0100000 - 0xc0320514 (2177 kB)
[ 9.990887] Checking if this processor honours the WP bit even in supervisor mode... Ok.
[ 9.990928] SLUB: Genslabs=11, HWalign=64, Order=0-1, MinObjects=4, CPUs=1, Nodes=1
[ 10.070784] Calibrating delay using timer specific routine.. 5191.67 BogoMIPS (lpj=10383340)
[ 10.070811] Security Framework initialized
[ 10.070818] SELinux: Disabled at boot.
[ 10.070833]...

Peter Cherriman (pjcherriman) wrote :

jtclicker are you sure it fixed it completely?

I thought intrepid used 2.6.27 kernels, but the uname command show in 2.6.24-21
Also it seems you still have the same -110, -32 error messages.

I found intrepid kernels (2.6.27) automatically mount my sansa clip, but only at usb1 speeds. Which is a improvement, but not a complete fix.

jtclicker (lists-ya) wrote :

I should have been clearer, sorry! The data attached is from gutsy, not intrepid. Under intrepid I didn't test the speeds, but it mounted itself and unmounted. Have you checked the speed issue? Would it help if I sent the data from intrepid?

jtclicker (lists-ya) wrote :
Download full text (38.3 KiB)

Data for intrepid

dmesg
[ 0.000000] #0 [0000000000 - 0000001000] BIOS data page ==> [0000000000 - 0000001000]
[ 0.000000] #1 [0000001000 - 0000002000] EX TRAMPOLINE ==> [0000001000 - 0000002000]
[ 0.000000] #2 [0000006000 - 0000007000] TRAMPOLINE ==> [0000006000 - 0000007000]
[ 0.000000] #3 [0000100000 - 00005dfba0] TEXT DATA BSS ==> [0000100000 - 00005dfba0]
[ 0.000000] #4 [00005e0000 - 00005e3000] INIT_PG_TABLE ==> [00005e0000 - 00005e3000]
[ 0.000000] #5 [000009fc00 - 0000100000] BIOS reserved ==> [000009fc00 - 0000100000]
[ 0.000000] #6 [0000007000 - 0000008000] PGTABLE ==> [0000007000 - 0000008000]
[ 0.000000] #7 [00005e3000 - 0000de0205] NEW RAMDISK ==> [00005e3000 - 0000de0205]
[ 0.000000] #8 [0000008000 - 000000f000] BOOTMAP ==> [0000008000 - 000000f000]
[ 0.000000] found SMP MP-table at [c00fe710] 000fe710
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0x00000000 -> 0x00001000
[ 0.000000] Normal 0x00001000 -> 0x00038000
[ 0.000000] HighMem 0x00038000 -> 0x0003ff74
[ 0.000000] Movable zone start PFN for each node
[ 0.000000] early_node_map[2] active PFN ranges
[ 0.000000] 0: 0x00000000 -> 0x000000a0
[ 0.000000] 0: 0x00000100 -> 0x0003ff74
[ 0.000000] On node 0 totalpages: 261908
[ 0.000000] free_area_init_node: node 0, pgdat c0490180, node_mem_map c1000000
[ 0.000000] DMA zone: 3964 pages, LIFO batch:0
[ 0.000000] Normal zone: 223300 pages, LIFO batch:31
[ 0.000000] HighMem zone: 32341 pages, LIFO batch:7
[ 0.000000] ACPI: PM-Timer IO Port: 0x808
[ 0.000000] ACPI: Local APIC address 0xfee00000
[ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x01] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x03] disabled)
[ 0.000000] ACPI: IOAPIC (id[0x01] address[0xfec00000] gsi_base[0])
[ 0.000000] IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.000000] ACPI: IRQ0 used by override.
[ 0.000000] ACPI: IRQ2 used by override.
[ 0.000000] ACPI: IRQ9 used by override.
[ 0.000000] Enabling APIC mode: Flat. Using 1 I/O APICs
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] SMP: Allowing 4 CPUs, 3 hotplug CPUs
[ 0.000000] mapped APIC to ffffb000 (fee00000)
[ 0.000000] mapped IOAPIC to ffffa000 (fec00000)
[ 0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000
[ 0.000000] PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
[ 0.000000] Allocating PCI resources starting at 50000000 (gap: 40000000:bec00000)
[ 0.000000] PERCPU: Allocating 41628 bytes of per cpu data
[ 0.000000] NR_CPUS: 64, nr_cpu_ids: 4, nr_node_ids 1
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 259605
[ 0.000000] Kernel command line: BOOT_IMAGE=/casper/vmlinuz file=/cdrom/...

Peter Cherriman (pjcherriman) wrote :

Here a summary for my sansa clip.

Under gutsy, debian lenny and a 2.6.27 kernel (from interpid):

My clip automounts but only at USB1 speeds

(Hint the easy way to check is do properties on the drive icon, click on drive tab, if connection says 12Mbps its USB1, 480Mbps is USB2)

However if I boot the PC with the clip plugged in, it automounts at USB2 speed. However, if I unplug it and plug it back in it connects at USB1 speeds.

On hardy, it also automounts at USB2 speeds if it plugged in before I boot. However if plug it in later it wont be detected. Sometimes I can get it detected by running "lsusb" a couple times. If that doesn't work unload and reloading the ehci_hcd module is the only way to get it detected, it then mounts at USB2 speed, until it is unplugged, and plugged back in, where again it isn't detected.

When the clip is plugged in after boot, on all the kernels I've tried I get the following error messages.

Sep 14 15:50:27 usb 8-3: new high speed USB device using ehci_hcd and address 3
Sep 14 15:50:29 ehci_hcd 0000:00:1d.7: port 3 reset error -110
Sep 14 15:50:29 hub 8-0:1.0: hub_port_status failed (err = -32)

the -110 is a timeout when reseting something, the kernel (ehci-hcd.c) has a 750usec delay with a comment to revisit the issue with some hardware, where 550usec was not enough. I've not worked out what -32 error message is yet.

On the gutsy, lenny and intrepid kernels, (but not hardy) it then automatically falls back to USB1 and automounts the clip (at USB1 speeds = full speed)

Sep 14 15:50:30 hub 8-0:1.0: unable to enumerate USB device on port 3
Sep 14 15:50:30 usb 5-1: new full speed USB device using uhci_hcd and address 2
Sep 14 15:50:30 usb 5-1: not running at top speed; connect to a high speed hub
Sep 14 15:50:30 usb 5-1: configuration #1 chosen from 1 choice
Sep 14 15:50:30 scsi7 : SCSI emulation for USB Mass Storage devices
Sep 14 15:50:30 usb-storage: device found at 2
Sep 14 15:50:30 usb-storage: waiting for device to settle before scanning
Sep 14 15:50:35 usb-storage: device scan complete
Sep 14 15:50:35 scsi 7:0:0:0: Direct-Access SanDisk Sansa Clip 2GB v01. PQ: 0 ANSI: 0
Sep 14 15:50:35 sd 7:0:0:0: [sdb] 3935232 512-byte hardware sectors (2015 MB)

It then needs the following command to get the clip to remount at USB2 speeds:

sudo modprobe -r ehci_hcd; sudo modprobe ehci_hcd

So in all the cases there is a problem with the clip. On gutsy, lenny, interpid kernels the clip is mounted but only at USB1 speeds. On hardy it doesn't automount. All kernels needs some command line work to get the clip to mount at USB2 speeds, and that only fixes the problem until it is unplugged.

If you boot the PC with the clip already plugged in, in automounts at USB2 speeds, but as before if you unplug it and then plug it back in it either doesn't mount or mounts at USB1 speeds depending on which kernel you are using.

Forest (foresto) wrote :
Download full text (4.9 KiB)

I'm having trouble connecting my Sansa Clip as well.

In Hardy, USB negotiation seems to fail when plugging into a USB port that's connected directly to the motherboard, but it works when plugging into the USB hub in my monitor.

In Intrepid alpha 6, high speed USB negotiation fails, and it falls back to "full" (slow) speed when plugging into a USB port that's connected directly to the motherboard. High speed works when plugging into the USB hub in my monitor. This seems odd, since the monitor's USB hub (which works) is itself plugged into one of the motherboard's ports (which fails).

Messages from syslog when plugging into my motherboard's USB port under Intrepid a6:

Sep 28 20:00:37 ubuntu kernel: [ 588.916011] usb 8-5: new high speed USB device using ehci_hcd and address 4
Sep 28 20:00:40 ubuntu kernel: [ 592.733355] ehci_hcd 0000:00:1d.7: port 5 reset error -110
Sep 28 20:00:40 ubuntu kernel: [ 592.733497] hub 8-0:1.0: hub_port_status failed (err = -32)
Sep 28 20:00:41 ubuntu kernel: [ 592.936031] hub 8-0:1.0: unable to enumerate USB device on port 5
Sep 28 20:00:41 ubuntu kernel: [ 593.192009] usb 7-1: new full speed USB device using uhci_hcd and address 4
Sep 28 20:00:41 ubuntu kernel: [ 593.391028] usb 7-1: not running at top speed; connect to a high speed hub
Sep 28 20:00:41 ubuntu kernel: [ 593.421466] usb 7-1: configuration #1 chosen from 1 choice
Sep 28 20:00:41 ubuntu kernel: [ 593.438002] scsi9 : SCSI emulation for USB Mass Storage devices
Sep 28 20:00:41 ubuntu kernel: [ 593.446920] usb-storage: device found at 4
Sep 28 20:00:41 ubuntu kernel: [ 593.446924] usb-storage: waiting for device to settle before scanning
Sep 28 20:00:46 ubuntu kernel: [ 598.446068] usb-storage: device scan complete
Sep 28 20:00:46 ubuntu kernel: [ 598.449063] scsi 9:0:0:0: Direct-Access SanDisk Sansa Clip 2GB v01. PQ: 0 ANSI: 0
Sep 28 20:00:46 ubuntu kernel: [ 598.459041] sd 9:0:0:0: [sdb] 3992576 512-byte hardware sectors (2044 MB)
Sep 28 20:00:46 ubuntu kernel: [ 598.471041] sd 9:0:0:0: [sdb] Write Protect is off
Sep 28 20:00:46 ubuntu kernel: [ 598.471046] sd 9:0:0:0: [sdb] Mode Sense: 04 00 00 00
Sep 28 20:00:46 ubuntu kernel: [ 598.471048] sd 9:0:0:0: [sdb] Assuming drive cache: write through
Sep 28 20:00:46 ubuntu kernel: [ 598.492828] sd 9:0:0:0: [sdb] 3992576 512-byte hardware sectors (2044 MB)
Sep 28 20:00:46 ubuntu kernel: [ 598.495031] sd 9:0:0:0: [sdb] Write Protect is off
Sep 28 20:00:46 ubuntu kernel: [ 598.495034] sd 9:0:0:0: [sdb] Mode Sense: 04 00 00 00
Sep 28 20:00:46 ubuntu kernel: [ 598.495036] sd 9:0:0:0: [sdb] Assuming drive cache: write through
Sep 28 20:00:46 ubuntu kernel: [ 598.495039] sdb:
Sep 28 20:00:46 ubuntu kernel: [ 598.504076] sd 9:0:0:0: [sdb] Attached SCSI removable disk
Sep 28 20:00:46 ubuntu kernel: [ 598.504150] sd 9:0:0:0: Attached scsi generic sg2 type 0
Sep 28 20:00:47 ubuntu hald: mounted /dev/sdb on behalf of uid 999

Messages from syslog when plugging into my monitor's USB port under Intrepid a6:

Sep 28 20:02:24 ubuntu kernel: [ 696.400119] usb 4-2.1: new high speed USB device using ehci_hcd and address 4
Sep 28 20:02:25 ubuntu kernel: [ 697.780872] hub 4-2:1.0: una...

Read more...

Andreas Moog (ampelbein) on 2009-03-19
Changed in linux (Ubuntu):
status: Incomplete → Confirmed
TJ (tj) on 2009-03-19
Changed in linux (Ubuntu):
assignee: nobody → intuitivenipple
TJ (tj) wrote :

It looks as if this issue is related to another USB speed issue, although not caused by or solved by it - bug #296710 "warning: ehci_hcd loaded AFTER uhci_hcd and ohci_hcd"

However, in this particular case it looks rather that the particular system hardware is getting confused and may be related to particular motherboard chipset/port combinations.

I'll explain a little as to how the hardware is organised so it is easier to understand.

The kernel's USB modules deal with each version of the USB protocol separately. The original USB v1.x low-speed and high-speed (12Mbs) is handled by uhci_hcd. USB v2 is handled by ehci_hcd (480Mbps).

The physical hardware of a PC has separate controller devices for each USB version. The PCI [vendor:model] ID determines which kernel module manages a device.

The physical external ports of a PC, when they support USB2 *and* USB v1.x devices, are usually *shared* by the host controllers. When the PC powers up (or resets) the first host controller to be initialised (by a kernel module) *claims* ports. Once claimed a port cannot be used by another host controller until a power reset. The kernel modules have no way to control which host controller claims ports.

From the various permutations of tests that have been done so far by users it looks as if this process of claiming external ports partially explains the symptoms, and may help us find a solution.

The key thing seems to be that all the reports seem to agree that this *just worked* on Gutsy for the reason that the ports were being handled by the USB v1.x (12Mbps) host controller on the orders of uhci_hcd.

In the later kernel releases the ports are being initialised by the USB v2 (480Mbps) host controller on the orders of ehci_hcd.

It is possible that this is specific to particular hardware - maybe motherboard make/model, possibly the conjunction of particular pairs of USB host controllers.

So, now the explanation is over, what we need is to gather that information to help look for commonalities. Please attach the reports from the following commands as single archives to make it easier to analyse.

----------
sudo -i
[ ! -x "$(which dmidecode)" ] && apt-get install dmidecode
mkdir /tmp/reports
uname -a >/tmp/reports/uname.log
lsb_release -a >/tmp/reports/lsb_release.log
dmidecode -t system >/tmp/reports/dmidecode.log
dmidecode -t baseboard >>/tmp/reports/dmidecode.log
lspci --vvnn >/tmp/reports/lspci-vvnn.log
lsusb -v >/tmp/reports/lsusb-v.log
dmesg >/tmp/reports/dmesg.log

tar -czf /tmp/system-report.tar.gz /tmp/reports/*

exit
----------

Now attach the resulting file "/tmp/system-report.tar.gz" to this bug report.

Peter Cherriman (pjcherriman) wrote :

Thanks TJ for taking an interest.

Looking at your script I think the lspci command is wrong since "lspci --vvnn" gives an error. Does it have an extra -?

I'm assume you want us to run the script maybe 30s after we plug the problem device (sansa clip) in?

I'll send the results in a few days when I have the device to hand.

Peter Cherriman (pjcherriman) wrote :

TJ can you give a possible explanation as to why running lsusb a few times gets the device detected?

TJ (tj) wrote :

Peter - oops: too many hyphen/switch characters ("--")

It should be a single hyphen switch:

lspci -vvnn >/tmp/reports/lspci-vvnn.log

As to an explanation, we might be able to deduce one once information from various systems is in. In theory lsusb shouldn't make any different since it is only supposed to be reading and reporting the configuration.

TJ (tj) wrote :

Peter, a a side project, I'd be interested to know if lsusb is opening any files or devices for write access, or otherwise touching a file/device in a way which changes its status.

If you can get the system into a state where the problem occurs and then repeatedly run lsusb until it fixes it, using the strace utility to log all activity by lsusb, and when it 'fixes' the issue, add a comment with the log-file attached, it may help us in pursuit of a solution. This is the command to run (you can add options to lsusb if you wish). "lsusb.log" is written to the current directory.

strace -o lsusb.log lsusb

Jaime Carpenter (j.carpenter) wrote :

Greetings, I also have a Sansa Clip, firmware v01.01.29A, and I am having the same symptoms described in this bug report. I am running Hardy 8.04 (kernel 2.6.24-22-generic).

I found a message on the Sansa forums talking about this problem and a proposed work around of unloading the ehci_hcd module. Also mentioned in this report.

http://forums.sandisk.com/sansa/board/message?board.id=clip&thread.id=8674

This will leave you with only USB1 speed as explained above in this report.

I have found another solution for me that gives USB2 (480Mbps) every time without unloading the ehci_hcd module. This is not optimal, but works:

* I plug in the Sansa Clip
* Sansa powers up and acts like it connects
* Hardy does not "see" it
* I hold the power off button on the Sansa until it powers off
* I release the power button then it powers up and connects at USB2 (480Mbps)

This process works every time for me.

I am willing to help and provide any information I can to resolve this problem. Reading on the Sansa forums, the opinion seemed to be a timing problem with the firmware. I can't speak to that issue, but I'll help test any way I can here.

On Thu, 2009-03-19 at 21:43 +0000, Jaime Carpenter wrote:

> I have found another solution for me that gives USB2 (480Mbps) every
> time without unloading the ehci_hcd module. This is not optimal, but
> works:
>
> * I plug in the Sansa Clip
> * Sansa powers up and acts like it connects
> * Hardy does not "see" it
> * I hold the power off button on the Sansa until it powers off
> * I release the power button then it powers up and connects at USB2 (480Mbps)
>
> This process works every time for me.

This tends to suggest the device itself incorrectly handles the USB
negotiation.

What make/model/revisions of devices are others using??

TJ (tj) wrote :

Something else occured to me about this. When this happens is the USB device connected to the port whilst the BIOS is POSTing?

For PCs who's BIOS support boot from USB this might/would trigger the BIOS into initialising at least one USB host controller which would claim the external port(s). It wouldn't surprise me if the BIOS only supported USB v1.1 and effectively tied the affected ports to the v1.1 controller.

Graham Hawkins (grahamhawkins) wrote :

Mine's a Fuze, but suffers the same problem. Firmware version is 01.01.22F

Mar 20 20:43:56 upstairs-linux kernel: [13103.668039] usb 1-6: new high speed USB device using ehci_hcd and address 4
Mar 20 20:43:57 upstairs-linux kernel: [13104.808036] usb 3-3: new full speed USB device using ohci_hcd and address 3
Mar 20 20:43:57 upstairs-linux kernel: [13105.007209] usb 3-3: not running at top speed; connect to a high speed hub

Peter Cherriman (pjcherriman) wrote :

TJ,

Find attached the system report for my 2gb Sansa Clip running firmware v01.01.32A in MSC connection mode.

I plugged in the sansa it wasn't detected in , I ran the your script, and the this caused the sansa to get detected and mounted at USB2 speed. Maybe I guess because of the lsusb command kicked it into life.

Peter Cherriman (pjcherriman) wrote :

lsusb wierdness. I plugged in my sansa clip, it wasn't detected.

I then run "strace -o lsusbfix.log lsusb"

The lsusb didn't show my sansa, only the ps2/usb keyboard/mouse adapter. However a few seconds later the sansa was detected and mounted automatically at USB2 speed.

You also asked about what happens if the sansa is plugged in before the system is booted, the sansa is mounted at boot at USB2 speed without any issues.

Peter Cherriman (pjcherriman) wrote :

The power off trick suggested by Jaime doesn't work for me however my sansa has a slightly newer firmware (v01.01.32A), and my PC has a slightly newer kernel on my hardy system (2.6.24-23-generic)

The "running lsusb a few times" trick works for me 95% of the time, only 100% (but awkward) fix I found was unloading ehci_hcd, device then remounts at USB1 speeds, then reloading ehci_hcd module and it remounts at USB2 speed with no problems.

However no fix is permenant, since ejecting, and unplugging, and then plugging back in is not detected until lsusb etc.

Hello TJ,

I'm grateful that someone's looking at this.

Are you able to rename this bug to something more appropriate?
   "Sandisk Sansa clip/furze doesn't mount in Hardy - usb connect issues"
Is a suggestion.

I have Hardy installed, and because it's broken a large number of
things, I restored a backup of Gutsy on another partition.
(Never thought I'd be happy to have Gutsy back)
So I'll run this test under both releases and attach the results.

Another thing that may be relevant is that the Sansa Clip has a
usb mode switch, either MTP, MSC or Auto Detect. This may be
effecting the usb timing in some way, so people should report it.

   Settings > USB Mode > MSC (used throughout in my case)

http://forums.sandisk.com/sansa/board/message?board.id=announcements&message.id=96&jump=true

Finally, the firmware version on the Clip may be relevant
so should be reported:

   Settings > System Info > Version:V01.01.30A

I also futzed with the mount point in some gnome thing so that it
would mount at /media/SANSA instead of a path full of spaces.

> So, now the explanation is over, what we need is to gather that
> information to help look for commonalities. Please attach the reports
> from the following commands as single archives to make it easier to
> analyse.

There's a gutsy report ("just works"), hardy plugged in but ignored,
and hardy after modprobe -r ehci_hcd so it mounted.

Happy to do additional reports if they'll help,

Brad

lepinkäinen (lepinkainen) wrote :

Even after trying all the tricks mentioned here my sansa clip is not mounting at all (not at usb 1.1 or via my keyboard's usb hub). I'm running Intrepid and the clip's firmware is 1.01.32.

Peter Cherriman (pjcherriman) wrote :

Firstly attached is a report, after I did the lsusb trick to get the sansa clip detected. This lists the sansa clip in the lsusb log which my previous report didn't.

lepinkäinen, I suggest you run the commands listed in comment 20 above (with correction from comment 23) and post the report file. Someone might be able to see what the problem is on your hardware.

I also noted that the sansa clip generates one of two different usb product_id (idProduct in lsusb) when configured in MSC or MTP or Auto modes.

Changed in linux (Ubuntu):
assignee: TJ (intuitivenipple) → nobody

jtclicker, this bug report is being closed due to your last comment regarding this being fixed with an update. For future reference you can manage the status of your own bugs by clicking on the current status in the yellow line and then choosing a new status in the revealed drop down box. You can learn more about bug statuses at https://wiki.ubuntu.com/Bugs/Status. Thank you again for taking the time to report this bug and helping to make Ubuntu better. Please submit any future bugs you may find.

Changed in linux (Ubuntu):
status: Confirmed → Invalid
affects: debian → null
Changed in null:
status: New → Invalid
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers