Hi
Here are dmesg's with old_scheme_first=1 and where it took about 20s
for usb-storage to start using this device. Is there a way I can
enable debugs from usb-storage to see what it is doing in that 20s
gap. The device in question is at usb1-3 (sdb), manufactured by SMART.
Thank you.
[ 1.628068] usb 1-3: new high speed USB device using ehci_hcd and address 2
[ 1.628073] usb 1-3: usenewscheme 0 retry_counter 0 i 0
[ 1.628103] EXT4-fs (sda1): warning: maximal mount count reached,
running e2fsck is recommended
[ 1.628671] EXT4-fs (sda1): recovery complete
[ 1.628680] EXT4-fs (sda1): mounted filesystem with ordered data mode
[ 1.649360] usb 1-3: default language 0x0409
[ 1.650118] usb 1-3: udev 2, busnum 1, minor = 1
[ 1.650123] usb 1-3: New USB device found, idVendor=0e39, idProduct=2b00
[ 1.650127] usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1.650131] usb 1-3: Product: eUSB
[ 1.650133] usb 1-3: Manufacturer: SMART
[ 1.650136] usb 1-3: SerialNumber: 29879006164049261011
[ 1.650311] usb 1-3: usb_probe_device
[ 1.650316] usb 1-3: configuration #1 chosen from 1 choice
[ 1.650465] usb 1-3: adding 1-3:1.0 (config #1, interface 0)
[ 1.650708] usb-storage 1-3:1.0: usb_probe_interface
[ 1.650716] usb-storage 1-3:1.0: usb_probe_interface - got id
[ 1.650927] scsi4 : SCSI emulation for USB Mass Storage devices
[ 1.651428] /bld/Kernel/Artools-rpmbuild/linux/drivers/usb/core/inode.c:
creating file '002'
[ 1.651453] hub 2-0:1.0: state 7 ports 5 chg 0020 evt 0000
[ 1.651464] hub 2-0:1.0: port 5, status 0501, change 0000, 480 Mb/s
[ 1.651477] usb-storage: device found at 2
[ 1.651770] usb-storage: device scan complete
[ 1.704076] ehci_hcd 0000:00:13.2: port 5 high speed
[ 1.704083] ehci_hcd 0000:00:13.2: GetStatus port 5 status 001005
POWER sig=se0 PE CONNECT
[ 1.760060] usb 2-5: new high speed USB device using ehci_hcd and address 2
[ 1.760065] usb 2-5: usenewscheme 0 retry_counter 0 i 0
[ 1.781500] usb 2-5: default language 0x0409
[ 1.781880] usb 2-5: udev 2, busnum 2, minor = 129
[ 1.781885] usb 2-5: New USB device found, idVendor=0781, idProduct=5571
[ 1.781888] usb 2-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1.781892] usb 2-5: Product: Cruzer Fit
[ 1.781895] usb 2-5: Manufacturer: SanDisk
[ 1.781897] usb 2-5: SerialNumber: 4C532008870615120374
[ 1.782072] usb 2-5: usb_probe_device
[ 1.782077] usb 2-5: configuration #1 chosen from 1 choice
[ 1.782228] usb 2-5: adding 2-5:1.0 (config #1, interface 0)
[ 1.782463] usb-storage 2-5:1.0: usb_probe_interface
[ 1.782471] usb-storage 2-5:1.0: usb_probe_interface - got id
[ 1.782678] scsi5 : SCSI emulation for USB Mass Storage devices
[ 1.783176] /bld/Kernel/Artools-rpmbuild/linux/drivers/usb/core/inode.c:
creating file '002'
[ 1.783202] hub 5-0:1.0: state 7 ports 5 chg 0000 evt 0000
[ 1.783207] hub 6-0:1.0: state 7 ports 4 chg 0000 evt 0000
[ 1.783212] usb-storage: device found at 2
[ 1.783532] usb-storage: device scan complete
[ 1.784053] scsi 5:0:0:0: Direct-Access SanDisk Cruzer Fit
1.26 PQ: 0 ANSI: 5
[ 22.872067] ehci_hcd 0000:00:12.2: port 3 high speed
[ 22.872075] ehci_hcd 0000:00:12.2: GetStatus port 3 status 001005
POWER sig=se0 PE CONNECT
[ 22.928057] usb 1-3: reset high speed USB device using ehci_hcd and address 2
[ 22.928062] usb 1-3: usenewscheme 0 retry_counter 0 i 0
[ 22.952867] scsi 4:0:0:0: Direct-Access SMART eUSB
883C PQ: 0 ANSI: 0 CCS
[ 22.955195] sd 4:0:0:0: [sdb] 4014080 512-byte logical blocks:
(2.05 GB/1.91 GiB)
[ 22.955724] sd 4:0:0:0: [sdb] Write Protect is off
[ 22.955730] sd 4:0:0:0: [sdb] Mode Sense: 43 00 00 00
[ 22.955733] sd 4:0:0:0: [sdb] Assuming drive cache: write through
[ 23.031197] sd 5:0:0:0: [sdc] 7821312 512-byte logical blocks:
(4.00 GB/3.72 GiB)
[ 23.032940] sd 5:0:0:0: [sdc] Write Protect is off
[ 23.032946] sd 5:0:0:0: [sdc] Mode Sense: 43 00 00 00
[ 23.032949] sd 5:0:0:0: [sdc] Assuming drive cache: write through
[ 23.118414] sd 4:0:0:0: [sdb] Assuming drive cache: write through
[ 23.191151] sdb: sdb1 sdb2
[ 23.194175] sd 5:0:0:0: [sdc] Assuming drive cache: write through
[ 23.266918] sdc:
[ 23.268744] sd 4:0:0:0: [sdb] Assuming drive cache: write through
[ 23.344071] sdc1
[ 23.344766] sd 4:0:0:0: [sdb] Attached SCSI disk
[ 23.346889] sd 5:0:0:0: [sdc] Assuming drive cache: write through
[ 23.419967] sd 5:0:0:0: [sdc] Attached SCSI removable disk
On Wed, Oct 30, 2013 at 3:21 PM, Prasad Koya <prasad.koya@xxxxxxxxx> wrote:
> Hi
>
> Thanks for suggesting the alternatives.
>
> With CONFIG_USB_DEBUG and CONFIG_USB_MON enabled I see below messages
> related to the USB device in question. This is not reproducible
> easily. I'll try the old_scheme_first. We are seeing this issue with
> flash that is internal to our box and not accessible outside and we
> ship them with this brand of flash. Will see if I can get usbmon
> traces.
>
> thank you.
>
> [ 1.306200] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> [ 1.306204] ehci_hcd: block sizes: qh 104 qtd 96 itd 192 sitd 96
> [ 1.306235] ehci_hcd 0000:00:12.2: PCI->APIC IRQ transform: INT B -> IRQ 23
> [ 1.306251] ehci_hcd 0000:00:12.2: EHCI Host Controller
> [ 1.306278] /bld/Kernel/Artools-rpmbuild/linux/drivers/usb/core/inode.c:
> creating file 'devices'
> [ 1.306288] /bld/Kernel/Artools-rpmbuild/linux/drivers/usb/core/inode.c:
> creating file '001'
> [ 1.306295] ehci_hcd 0000:00:12.2: new USB bus registered, assigned
> bus number 1
> [ 1.306305] ehci_hcd 0000:00:12.2: reset hcs_params 0x101505 dbg=1
> cc=1 pcc=5 ordered !ppc ports=5
> [ 1.306311] ehci_hcd 0000:00:12.2: reset hcc_params a072 thresh 7
> uframes 256/512/1024
> [ 1.306343] ehci_hcd 0000:00:12.2: debug port 1
> [ 1.306350] ehci_hcd 0000:00:12.2: reset command 01002a (park)=0
> ithresh=1 Async period=256 Reset HALT
> [ 1.306360] ehci_hcd 0000:00:12.2: MWI active
> [ 1.306378] ehci_hcd 0000:00:12.2: irq 23, io mem 0xe4113400
> [ 1.306385] ehci_hcd 0000:00:12.2: reset command 080002 (park)=0
> ithresh=8 period=1024 Reset HALT
> [ 1.306393] ehci_hcd 0000:00:12.2: init command 010009 (park)=0
> ithresh=1 period=256 RUN
> [ 1.316049] ehci_hcd 0000:00:12.2: USB 2.0 started, EHCI 1.00
> [ 1.316090] usb usb1: default language 0x0409
> [ 1.316100] usb usb1: udev 1, busnum 1, minor = 0
> [ 1.316104] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
> [ 1.316107] usb usb1: New USB device strings: Mfr=3, Product=2,
> SerialNumber=1
> [ 1.316111] usb usb1: Product: EHCI Host Controller
> [ 1.316114] usb usb1: Manufacturer: Linux 2.6.32.28.Ar-150692 ehci_hcd
> [ 1.316118] usb usb1: SerialNumber: 0000:00:12.2
> [ 1.316238] usb usb1: usb_probe_device
> [ 1.316243] usb usb1: configuration #1 chosen from 1 choice
> [ 1.316253] usb usb1: adding 1-0:1.0 (config #1, interface 0)
> [ 1.316316] hub 1-0:1.0: usb_probe_interface
> [ 1.316319] hub 1-0:1.0: usb_probe_interface - got id
> [ 1.316322] hub 1-0:1.0: USB hub found
> [ 1.316335] hub 1-0:1.0: 5 ports detected
> [ 1.316338] hub 1-0:1.0: standalone hub
> [ 1.316341] hub 1-0:1.0: no power switching (usb 1.0)
> [ 1.316343] hub 1-0:1.0: individual port over-current protection
> [ 1.316347] hub 1-0:1.0: power on to power good time: 20ms
> [ 1.316354] hub 1-0:1.0: local power source is good
> [ 1.316357] hub 1-0:1.0: trying to enable port power on non-switchable hub
> :
> [ 1.340448] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
> [ 1.340451] ohci_hcd: block sizes: ed 80 td 96
> [ 1.340475] ohci_hcd 0000:00:12.0: PCI->APIC IRQ transform: INT A -> IRQ 22
> [ 1.340494] ohci_hcd 0000:00:12.0: OHCI Host Controller
> [ 1.340504] /bld/Kernel/Artools-rpmbuild/linux/drivers/usb/core/inode.c:
> creating file '004'
> [ 1.340511] ohci_hcd 0000:00:12.0: new USB bus registered, assigned
> bus number 4
> [ 1.340525] ohci_hcd 0000:00:12.0: enabled AMD prefetch quirk
> [ 1.340535] ohci_hcd 0000:00:12.0: created debug files
> [ 1.340545] ohci_hcd 0000:00:12.0: irq 22, io mem 0xe4110000
> [ 1.400028] ohci_hcd 0000:00:12.0: OHCI controller state
> [ 1.400036] ohci_hcd 0000:00:12.0: OHCI 1.0, NO legacy support registers
> [ 1.400041] ohci_hcd 0000:00:12.0: control 0x083 HCFS=operational CBSR=3
> [ 1.400046] ohci_hcd 0000:00:12.0: cmdstatus 0x00000 SOC=0
> [ 1.400051] ohci_hcd 0000:00:12.0: intrstatus 0x00000004 SF
> [ 1.400056] ohci_hcd 0000:00:12.0: intrenable 0x8000005a MIE RHSC UE RD WDH
> [ 1.400067] ohci_hcd 0000:00:12.0: hcca frame #0005
> [ 1.400072] ohci_hcd 0000:00:12.0: roothub.a 02000205 POTPGT=2 NPS NDP=5(5)
> [ 1.400077] ohci_hcd 0000:00:12.0: roothub.b 00000000 PPCM=0000 DR=0000
> [ 1.400082] ohci_hcd 0000:00:12.0: roothub.status 00008000 DRWE
> [ 1.400087] ohci_hcd 0000:00:12.0: roothub.portstatus [0] 0x00000100 PPS
> [ 1.400092] ohci_hcd 0000:00:12.0: roothub.portstatus [1] 0x00000100 PPS
> [ 1.400097] ohci_hcd 0000:00:12.0: roothub.portstatus [2] 0x00000100 PPS
> [ 1.400102] ohci_hcd 0000:00:12.0: roothub.portstatus [3] 0x00000100 PPS
> [ 1.400107] ohci_hcd 0000:00:12.0: roothub.portstatus [4] 0x00000100 PPS
> :
> [ 1.572140] ehci_hcd 0000:00:12.2: port 3 high speed
> [ 1.572146] ehci_hcd 0000:00:12.2: GetStatus port 3 status 001005
> POWER sig=se0 PE CONNECT
> :
> [ 1.628093] usb 1-3: new high speed USB device using ehci_hcd and address 2
> :
> [ 6.628159] usb 1-3: khubd timed out on ep0in len=0/64
> [ 7.665178] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 1
> [ 7.665428] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 2
> [ 7.665677] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 3
> [ 7.665927] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 4
> [ 7.666176] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 5
> [ 7.666426] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 6
> [ 7.666676] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 7
> [ 7.666926] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 8
> [ 7.667176] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 9
> [ 7.667425] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 10
> [ 7.667675] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 11
> [ 7.667925] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 12
> [ 7.668180] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 13
> [ 7.668429] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 14
> [ 7.668678] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 15
> [ 7.668928] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 16
> [ 7.669178] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 17
> [ 7.669428] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 18
> [ 7.669678] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 19
> [ 7.669927] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 20
> [ 7.670177] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 21
> [ 7.670426] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 22
> [ 7.670676] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 23
> [ 7.670926] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 24
> [ 7.671176] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 25
> [ 7.671425] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 26
> [ 7.671675] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 27
> [ 7.671925] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 28
> [ 7.672180] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 29
> [ 7.672429] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 30
> [ 7.672679] ehci_hcd 0000:00:12.2: detected XactErr len 0/64 retry 31
> [ 7.672928] ehci_hcd 0000:00:12.2: devpath 3 ep0in 3strikes
> [ 7.673302] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 1
> [ 7.673552] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 2
> [ 7.673802] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 3
> [ 7.674052] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 4
> [ 7.674302] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 5
> [ 7.674552] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 6
> [ 7.674801] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 7
> [ 7.675051] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 8
> [ 7.675301] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 9
> [ 7.675550] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 10
> [ 7.675800] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 11
> [ 7.676045] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 12
> [ 7.676304] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 13
> [ 7.676554] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 14
> [ 7.676804] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 15
> [ 7.677053] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 16
> [ 7.677303] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 17
> [ 7.677553] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 18
> [ 7.677803] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 19
> [ 7.678052] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 20
> [ 7.678302] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 21
> [ 7.678552] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 22
> [ 7.678801] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 23
> [ 7.679051] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 24
> [ 7.679301] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 25
> [ 7.679550] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 26
> [ 7.679800] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 27
> [ 7.680045] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 28
> [ 7.680304] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 29
> [ 7.680554] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 30
> [ 7.680804] ehci_hcd 0000:00:12.2: detected XactErr len 0/8 retry 31
> [ 7.681053] ehci_hcd 0000:00:12.2: devpath 3 ep0in 3strikes
> [ 7.736055] ehci_hcd 0000:00:12.2: port 3 full speed --> companion
> [ 7.736064] ehci_hcd 0000:00:12.2: GetStatus port 3 status 003801
> POWER OWNER sig=j CONNECT
>
> On Wed, Oct 30, 2013 at 7:48 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
>> On Tue, 29 Oct 2013, Prasad Koya wrote:
>>
>>> Thanks for looking into the patch. Am fairly new to the USB subsystem.
>>> You are right. There is a possibility of going into infinite loop with
>>> hub_port_init -> usb_reset_device -> usb_reset_and_verify_device ->
>>> hub_port_init.
>>>
>>> We are trying to achieve two things inside crash_kexec'ed kerrnel:
>>>
>>> 1. avoid the 5s timeout during get_device_descriptor
>>> 2. and get USB device working
>>>
>>> When I tried this in hub_port_init() (in 2.6.38)
>>>
>>> default:
>>> if (r == 0)
>>> r = -EPROTO;
>>> break;
>>> }
>>>
>>> + if (r == -ETIMEDOUT) {
>>> + if(udev->speed == USB_SPEED_HIGH) {
>>> + dev_info(&udev->dev,
>>> "%s: force maxpktsize\n",
>>> + __FUNCTION__);
>>> + buf->bMaxPacketSize0 = 64;
>>> + r = 0;
>>> + break;
>>> + }
>>> + }
>>
>> I prefer not to do it this way. First, because it avoids the retry
>> loop, and second, because the same technique can apply to other speeds,
>> not only high speed.
>>
>>> the function completed fine i.e., even hub_port_reset below went fine
>>> with wPortStatus reflecting that reset is complete. However, 20s after
>>> that the USB block driver had called usb_reset_device() and the device
>>> is accessible since then.
>>
>> I can't understand this last sentence. 20 seconds after what -- the
>> reset? Do you mean usb-storage rather than USB block driver?
>> usb-storage called usb_reset_device 20 seconds after the reset was
>> complete? The device is accessible since when (the first reset or the
>> second)?
>>
>>> When usb_reset_device was called by higher
>>> layer, the state of the USB is CONFIGURED. Below is the backtrace to
>>> usb_reset_device.
>>
>> The backtrace only tells you that usb-storage called
>> usb_reset_device. If you want to know _why_ it called
>> usb_reset_device, you need to collect a usbmon trace.
>>
>>> As you suggested earlier, I'm thinking of if there is a way to
>>> unbind/rebind the driver. From above backtrace and after looking at
>>> usb_reset_device(), I thought usb_reset_device() is doing the
>>> unbind/rebind.
>>
>> Why do you want to unbind and rebind usb-storage?
>>
>>> Since I'm seeing 'r' as -110 (ETIMEDOUT) or -71 (EPROTO) (EPROTO on
>>> later 2 retries), the code you gave in first part of your patch would
>>> never get executed.
>>>
>>> Thanks for your help.
>>
>> Maybe it would be best to switch devices instead of trying to change
>> the driver. Find a device that complies with the USB spec.
>>
>> Alternatively, you could create a new quirk flag for this device. When
>> that flag is set, you could skip the 64-byte Get-Descriptor entirely.
>>
>> Or you could try setting the "usbcore.old_scheme_first=1" option in the
>> kernel command line. That might be the easiest answer.
>>
>> Alan Stern
>>
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
