Resending in plain-text. On Thu, Oct 24, 2013 at 11:06 PM, Prasad Koya <prasad.koya@xxxxxxxxx> wrote: > Hi > > I tried with even unmounting the USB before forcing panic and I see same > time out while getting device descriptor. > > From debugs, I see that the portstatus is 0x501 to start with ie, > (high-speed attached, power-on, device is attached). After reset I see > wPortStatus and wPortChange bits as expected. However, get descriptor > timesout with status as -ENOENT. If I ignore this error and set > bMaxPacketSize0 to 64, it gets through the initialization but i see > usb-storage driver doing a reset much later. > > Pl see the debugs: > > [ 1.516055] hub 1-0:1.0: state 7 ports 5 chg 0008 evt 0000 > [ 1.516060] hub 1-0:1.0: nbr ports 5 > [ 1.516087] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 1.516090] hub 1-0:1.0: hub_port_status: port1 3 0x501 0x0 <==== XXX > ==== > [ 1.516094] hub 1-0:1.0: port3 0x501 0x0 ret 0 connchng -1 > [ 1.516107] hub 1-0:1.0: port 3, status 0501, change 0000, 480 Mb/s > [ 1.516119] hub 1-0:1.0: hub_port_connect_change 3209 > [ 1.516123] hub 1-0:1.0: call hub_port_init hub_port_connect_change 3247 > [ 1.516199] usb 1-3: hub_port_init 2747: speed 0 > [ 1.516202] hub 1-0:1.0: resetting port > [ 1.516220] hub 1-0:1.0: reset port 3 (err = 0) > [ 1.522147] hub 1-0:1.0: usb_device_match > [ 1.572069] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 1.572073] hub 1-0:1.0: hub_port_status: port1 3 0x503 0x10 <===== XXX > ===== (reset complete) > [ 1.572076] hub 1-0:1.0: port 3 status 0x503 change 0x10 ret 0 > [ 1.572080] hub 1-0:1.0: hub_port_wait_reset 2008 speed 3 > [ 1.572083] hub 1-0:1.0: hub_port_reset port_wait_reset: err = 0 > [ 1.628044] hub 1-0:1.0: update_address > [ 1.628073] hub 1-0:1.0: hub_port_reset port 3. status 0 2164 > [ 1.628076] usb 1-3: hub_port_init 2762: retval 0 > [ 1.628080] usb 1-3: new high speed USB device using ehci_hcd and address > 2 > [ 1.628083] usb 1-3: hub_port_init get DESCRIPTOR > [ 1.628087] usb 1-3: try 0 2868 > [ 1.628089] usb 1-3: usb_start_wait_urb timeout 5000 > [ 6.628080] usb 1-3: khubd timed out on ep0in len=0/64 status -2 ==> > -ENOENT > [ 6.628097] usb 1-3: hub_port_init: iter 0 maxpktsize 0 r -110 ==> > -ETIMEDOUT > [ 6.628101] usb 1-3: hub_port_init: force maxpktsize > [ 6.628104] usb 1-3: hub_port_init: call hub_port_reset 2907 port 3 > [ 6.628130] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 6.628133] hub 1-0:1.0: hub_port_status: port1 3 0x503 0x0 > [ 6.628137] usb 1-3: hub_port_init: port_status 2913 ret 0 0x503 0x0 > [ 6.628141] hub 1-0:1.0: resetting port > [ 6.628159] hub 1-0:1.0: reset port 3 (err = 0) > [ 6.684097] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 6.684100] hub 1-0:1.0: hub_port_status: port1 3 0x503 0x10 > [ 6.684104] hub 1-0:1.0: port 3 status 0x503 change 0x10 ret 0 > [ 6.684108] hub 1-0:1.0: hub_port_wait_reset 2008 speed 3 > [ 6.684111] hub 1-0:1.0: hub_port_reset port_wait_reset: err = 0 > [ 6.740044] hub 1-0:1.0: update_address > [ 6.740073] hub 1-0:1.0: hub_port_reset port 3. status 0 2164 > [ 6.740077] usb 1-3: hub_port_init: hub_port_reset 2917 port 3 rv 0 > [ 6.740080] usb 1-3: usb_start_wait_urb timeout 5000 > [ 6.744048] usb 1-3: usb_ep0_reinit > [ 6.760049] usb 1-3: usb_start_wait_urb timeout 5000 > [ 6.760477] hub 1-0:1.0: call hub_port_init hub_port_connect_change 3249 > status 0x0 > [ 6.760485] usb 1-3: usb_start_wait_urb timeout 5000 > [ 6.761221] usb 1-3: default language 0x0409 > [ 6.761226] usb 1-3: usb_start_wait_urb timeout 5000 > [ 6.761973] usb 1-3: udev 2, busnum 1, minor = 1 > [ 6.761976] usb 1-3: New USB device found, idVendor=0e39, idProduct=2b00 > [ 6.761979] usb 1-3: New USB device strings: Mfr=1, Product=2, > SerialNumber=3 > [ 6.761982] usb 1-3: Product: eUSB > [ 6.761985] usb 1-3: Manufacturer: SMART > [ 6.761987] usb 1-3: SerialNumber: 3E3B2F01123531050102 > [ 6.762265] usb 1-3: usb_device_match > [ 6.762457] usb 1-3: configuration #1 chosen from 1 choice > [ 6.762462] usb 1-3: usb_start_wait_urb timeout 5000 > [ 6.763226] usb 1-3: adding 1-3:1.0 (config #1, interface 0) > [ 6.763519] usb 1-3:1.0: usb_device_match > [ 6.764961] hub 1-0:1.0: hub_events 3553 > [ 27.816144] usb 1-3: usb_reset_device in state 7 > [ 27.816153] usb 1-3: usb_ep0_reinit > [ 27.816156] usb_reset_and_verify_device: 3797 calling hub_port_init > [ 27.816161] Pid: 522, comm: usb-storage Not tainted 2.6.32.28.Ar-1399732 > #49 > [ 27.816165] Call Trace: > [ 27.816174] [<ffffffff81204908>] hub_port_init+0x3b/0x9f3 > [ 27.816181] [<ffffffff812054a7>] usb_reset_device+0x1e7/0x6ed > [ 27.816188] [<ffffffff81221459>] usb_stor_port_reset+0x31/0x4e > [ 27.816192] [<ffffffff81221ace>] usb_stor_invoke_transport+0x2c3/0x31e > [ 27.816199] [<ffffffff8131405c>] ? __mutex_lock_slowpath+0x26c/0x294 > [ 27.816204] [<ffffffff812213a3>] > usb_stor_transparent_scsi_command+0x9/0xb > [ 27.816209] [<ffffffff81223170>] usb_stor_control_thread+0x13b/0x1d8 > [ 27.816215] [<ffffffff81315651>] ? _spin_unlock_irqrestore+0x36/0x3a > [ 27.816219] [<ffffffff81223035>] ? usb_stor_control_thread+0x0/0x1d8 > [ 27.816226] [<ffffffff81047c9b>] kthread+0x7a/0x82 > [ 27.816232] [<ffffffff8100c9ea>] child_rip+0xa/0x20 > [ 27.816237] [<ffffffff81047c21>] ? kthread+0x0/0x82 > [ 27.816241] [<ffffffff8100c9e0>] ? child_rip+0x0/0x20 > [ 27.816245] usb 1-3: hub_port_init 2747: speed 3 > [ 27.816248] hub 1-0:1.0: resetting port > [ 27.816272] hub 1-0:1.0: reset port 3 (err = 0) > [ 27.872086] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 27.872089] hub 1-0:1.0: hub_port_status: port1 3 0x503 0x10 > [ 27.872094] hub 1-0:1.0: port 3 status 0x503 change 0x10 ret 0 > [ 27.872097] hub 1-0:1.0: hub_port_wait_reset 2008 speed 3 > [ 27.872100] hub 1-0:1.0: hub_port_reset port_wait_reset: err = 0 > [ 27.928045] hub 1-0:1.0: update_address > [ 27.928073] hub 1-0:1.0: hub_port_reset port 3. status 0 2164 > [ 27.928076] usb 1-3: hub_port_init 2762: retval 0 > [ 27.928081] usb 1-3: reset high speed USB device using ehci_hcd and > address 2 > [ 27.928084] usb 1-3: hub_port_init get DESCRIPTOR > [ 27.928088] usb 1-3: try 0 2868 > [ 27.928091] usb 1-3: usb_start_wait_urb timeout 5000 > [ 27.928415] usb 1-3: hub_port_init: iter 0 maxpktsize 64 r 18 > [ 27.928419] usb 1-3: hub_port_init: call hub_port_reset 2907 port 3 > [ 27.928445] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 27.928448] hub 1-0:1.0: hub_port_status: port1 3 0x503 0x0 > [ 27.928452] usb 1-3: hub_port_init: port_status 2913 ret 0 0x503 0x0 > [ 27.928455] hub 1-0:1.0: resetting port > [ 27.928474] hub 1-0:1.0: reset port 3 (err = 0) > [ 27.984100] hub 1-0:1.0: hub_port_status: port1 3 ret 4 > [ 27.984103] hub 1-0:1.0: hub_port_status: port1 3 0x503 0x10 > [ 27.984107] hub 1-0:1.0: port 3 status 0x503 change 0x10 ret 0 > [ 27.984111] hub 1-0:1.0: hub_port_wait_reset 2008 speed 3 > [ 27.984113] hub 1-0:1.0: hub_port_reset port_wait_reset: err = 0 > [ 28.040044] hub 1-0:1.0: update_address > [ 28.040072] hub 1-0:1.0: hub_port_reset port 3. status 0 2164 > [ 28.040076] usb 1-3: hub_port_init: hub_port_reset 2917 port 3 rv 0 > [ 28.040080] usb 1-3: usb_start_wait_urb timeout 5000 > [ 28.044049] usb 1-3: usb_ep0_reinit > [ 28.060049] usb 1-3: usb_start_wait_urb timeout 5000 > [ 28.060407] usb 1-3: usb_start_wait_urb timeout 5000 > [ 28.060777] usb 1-3: usb_start_wait_urb timeout 5000 > [ 28.061153] usb 1-3: usb_start_wait_urb timeout 5000 > [ 28.061404] usb 1-3: usb_reset_device ret 0 > [ 28.064423] scsi 4:0:0:0: Direct-Access SMART eUSB > 883C PQ: 0 ANSI: 0 CCS > [ 28.066899] sd 4:0:0:0: [sda] 4014080 512-byte logical blocks: (2.05 > GB/1.91 GiB) > [ 28.067533] sd 4:0:0:0: [sda] Write Protect is off > [ 28.067539] sd 4:0:0:0: [sda] Mode Sense: 43 00 00 00 > [ 28.067542] sd 4:0:0:0: [sda] Assuming drive cache: write through > [ 28.068913] sd 4:0:0:0: [sda] Assuming drive cache: write through > [ 28.068923] sda: sda1 sda2 > [ 28.072744] sd 4:0:0:0: [sda] Assuming drive cache: write through > [ 28.072749] sd 4:0:0:0: [sda] Attached SCSI disk > > > Thanks for your time. > > > On Wed, Oct 23, 2013 at 7:49 AM, Prasad Koya <prasad.koya@xxxxxxxxx> wrote: >> >> Hi >> >> Thanks for pointing to right mailing-list. >> >> We use crash_kexec'd kernel to copy out dmesg (vmcore-dmesg) to see what >> went wrong in main kernel. While testing to see if this mechanism works, I >> force main kernel to crash by calling BUG() from a known code path. >> >> I even tried the logic to retry resetting a few times with a gap of 200ms >> (HUB_LONG_RESET_TIME) upto a second. That didn't help either. >> >> I'll check if anything in the system is using USB while I force the crash. >> >> Thanks. >> >> >> On Wed, Oct 23, 2013 at 7:18 AM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> >> wrote: >>> >>> On Tue, 22 Oct 2013, Prasad Koya wrote: >>> >>> > Hi >>> > >>> > I have a USB subsystem question. If there is a specific mailing list >>> > for >>> > USB queries I could post it there. >>> >>> The specific mailing list for USB queries is >>> <linux-usb@xxxxxxxxxxxxxxx>. It's listed in the kernel's MAINTAINERS >>> file. >>> >>> > I'm seeing this problem with both 2.6.38 >>> > and 3.4 kernels. >>> >>> Have you tried anything more up to date, such as 3.11? >>> >>> > I have an embedded system that boots off flash. If the main kernel >>> > crashes, >>> >>> Why does your kernel crash? That should be the first thing you want to >>> fix. >>> >>> > we go into another kernel to save dmesg from previous kernel. Inside >>> > crash_kexec'ed kernel, we wait for same flash that main kernel booted >>> > off >>> > to be mounted before we copy out the dmesg from old kernel. At times, I >>> > see >>> > this error inside crash_kexec'ed kernel: >>> > >>> > usb 1-3: khubd timed out on ep0in len=0/64 >>> > >>> > and the USB flash fails to come up with ehci driver. CONFIG_PM is not >>> > defined. >>> > >>> > Here are some more debugs with return codes around this. I >>> > tried USB_PORT_FEAT_SUSPEND before USB_PORT_FEAT_RESET and I get EPIPE. >>> > >>> > [ 6.628118] usb 1-3: khubd timed out on ep0in len=0/64 status -2 >>> > [ 6.628124] usb_start_wait_urb 78: retval -110 status -2 >>> > [ 6.628128] usb_internal_control_msg retv -110 len 0 >>> > [ 6.628132] usb_control_msg pipe 80000080 reqtype 80 ret -110 >>> > [ 6.628135] hub_port_init: iter 0 maxpktsize 0 r -110 >>> > [ 6.628140] usb 1-3: usb_start_wait_urb timeout 5000 >>> > [ 7.793311] usb_start_wait_urb 78: retval -71 status -71 >>> > [ 7.793316] usb_internal_control_msg retv -71 len 0 >>> > [ 7.793319] usb_control_msg pipe 80000080 reqtype 80 ret -71 >>> > [ 7.793323] hub_port_init: iter 1 maxpktsize 0 r -71 >>> > [ 7.793328] usb 1-3: usb_start_wait_urb timeout 5000 >>> > [ 7.801435] usb_start_wait_urb 78: retval -71 status -71 >>> > [ 7.801439] usb_internal_control_msg retv -71 len 0 >>> > [ 7.801443] usb_control_msg pipe 80000080 reqtype 80 ret -71 >>> > [ 7.801446] hub_port_init: iter 2 maxpktsize 0 r -71 >>> > [ 7.801452] usb usb1: usb_start_wait_urb timeout 1000 >>> > [ 7.801459] usb_start_wait_urb 78: retval -32 status -32 >>> > [ 7.801461] usb_internal_control_msg retv -32 len 0 >>> > [ 7.801464] usb_control_msg pipe 80000100 reqtype 23 ret -32 >>> > [ 7.801468] hub 1-0:1.0: suspend port 3 (err = -32) >>> >>> It looks like the firmware in the USB flash device has crashed. That >>> could explain the original kernel crash. >>> >>> Or maybe the kernel crashed while the flash device was in the middle of >>> executing a command. Lots of USB storage devices don't reset properly >>> when that happens. >>> >>> > Appreciate any help/pointers. >>> >>> The kernel log from the time of the original crash might provide some >>> clues. >>> >>> 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
