On 01/09/2017 01:30 PM, Mathias Nyman wrote: > > On 09.01.2017 11:51, Patrice Chotard wrote: >> Hi Mathias, Greg > > Hi > >> >> I am working on ARM STi platform, since v4.10-rc1, when booting B2260 or B2120 STi boards platform >> with nothing plugged on USB3 connector, i observed the following kernel logs : >> >> .... >> [ 801.953836] usb usb6-port1: Cannot enable. Maybe the USB cable is bad? > > That's odd, why does it try to reset the port if there's nothing there? > >> [ 801.960455] xhci-hcd xhci-hcd.0.auto: Cannot set link state. > > This makes sense, nothing is connected, and we try to set link to U3 (PORT_PE == 0) > >> [ 801.966611] usb usb6-port1: cannot disable (err = -32) > xhci reutns -EPIPE as we try to set link state to U3 while port is not enabled (PORT_PE == 0) > >> [ 806.083772] usb usb6-port1: Cannot enable. Maybe the USB cable is bad? > > Again, about 5 seconds later the same port is reset, while nothing is connected. > Odd > >> [ 806.090370] xhci-hcd xhci-hcd.0.auto: Cannot set link state. >> [ 806.096494] usb usb6-port1: cannot disable (err = -32) >> [ 810.208766] usb usb6-port1: Cannot enable. Maybe the USB cable is bad? >> [ 810.215374] xhci-hcd xhci-hcd.0.auto: Cannot set link state. >> [ 810.221478] usb usb6-port1: cannot disable (err = -32) >> [ 814.333767] usb usb6-port1: Cannot enable. Maybe the USB cable is bad? >> [ 814.340364] xhci-hcd xhci-hcd.0.auto: Cannot set link state. >> ..... >> >> Another interesting thing is even if i plugged a device (a mass storage device in my case) on the USB3 connector, >> the above logs continue to appear. >> >> This is due to commit 37be66767e3ca "usb: hub: Fix auto-remount of safely removed or ejected USB-3 devices". >> >> I don't know if STi platforms are the only impacted by this issue. >> >> On v4.9 everything was ok. >> > > Was there not a single "Cannot enable. Maybe USB cable is bad" message with 4.9? There is no "Cannot enable. Maybe USB cable is bad" message with 4.9 > > Before commit 37be66767e3ca we forced the port to RxDetect state via Disabled state, > and cleared port change flags when a usb3_port_disable() was called. > > after we just set the port to U3. Maybe those STi platforms depend on that cycle somehow? I really don't know :-( > > Could you take logs (dmesg) of both 4.9 and 4.10-rc1 with both usb core and xhci debugging enabled: > > echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control > echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control You will find below the 2 requested logs, in both case , no USB cable are plugged. v4.9 dmesg logs : ..... [ 31.368022] hub 6-0:1.0: hub_resume [ 31.368064] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x400340 [ 31.368071] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340 [ 31.368224] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0000 [ 31.368269] xhci-hcd xhci-hcd.0.auto: set port remote wake mask, actual port 0 status = 0xe400340 [ 31.368332] hub 6-0:1.0: hub_suspend [ 31.368397] usb usb6: bus auto-suspend, wakeup 1 [ 31.368412] usb usb6: suspend raced with wakeup event [ 31.368418] usb usb6: usb auto-resume [ 31.388501] hub 6-0:1.0: hub_resume [ 31.388543] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x400340 [ 31.388553] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340 [ 31.388712] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0000 [ 31.388789] xhci-hcd xhci-hcd.0.auto: set port remote wake mask, actual port 0 status = 0xe400340 [ 31.388877] hub 6-0:1.0: hub_suspend [ 31.388945] usb usb6: bus auto-suspend, wakeup 1 [ 31.388961] usb usb6: suspend raced with wakeup event [ 31.388967] usb usb6: usb auto-resume [ 31.403021] hub 6-0:1.0: hub_resume [ 31.403064] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x400340 [ 31.403072] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x400340 [ 31.403186] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0000 [ 31.403228] xhci-hcd xhci-hcd.0.auto: set port remote wake mask, actual port 0 status = 0xe400340 [ 31.403294] hub 6-0:1.0: hub_suspend [ 31.403347] usb usb6: bus auto-suspend, wakeup 1 [ 31.403362] usb usb6: suspend raced with wakeup event [ 31.403368] usb usb6: usb auto-resume .... v4.10-rc1 dmesg logs : .... [ 269.436617] usb usb6-port1: cannot disable (err = -32) [ 269.464728] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002 [ 269.464756] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 269.464764] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 269.464823] usb usb6-port1: do warm reset [ 269.523075] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping port polling. [ 269.523139] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2b0 [ 269.523149] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x2b0 [ 269.523215] usb usb6-port1: not warm reset yet, waiting 50ms [ 269.564623] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 2 [ 269.564638] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling. [ 269.583142] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 269.583155] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 269.583221] usb usb6-port1: not warm reset yet, waiting 200ms [ 269.793108] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 269.793121] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 269.793186] usb usb6-port1: not warm reset yet, waiting 200ms [ 270.003194] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 270.003211] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 270.003331] usb usb6-port1: not warm reset yet, waiting 200ms [ 270.213164] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 270.213179] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 270.213252] usb usb6-port1: not warm reset yet, waiting 200ms [ 270.213274] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual port 0 status = 0x480340 [ 270.213330] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset change, actual port 0 status = 0x400340 [ 270.213381] xhci-hcd xhci-hcd.0.auto: clear port link state change, actual port 0 status = 0x340 [ 270.213432] xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x340 [ 270.213482] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 270.213490] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 270.213532] usb usb6-port1: not enabled, trying warm reset again... [ 270.273122] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping port polling. [ 270.313093] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 2 [ 270.313110] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling. [ 270.423105] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 270.423119] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 270.423188] usb usb6-port1: not warm reset yet, waiting 200ms [ 270.633157] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 270.633170] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 270.633251] usb usb6-port1: not warm reset yet, waiting 200ms [ 270.843105] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 270.843118] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 270.843195] usb usb6-port1: not warm reset yet, waiting 200ms [ 271.053106] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 271.053120] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 271.053200] usb usb6-port1: not warm reset yet, waiting 200ms [ 271.053224] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual port 0 status = 0x480340 [ 271.053284] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset change, actual port 0 status = 0x400340 [ 271.053337] xhci-hcd xhci-hcd.0.auto: clear port link state change, actual port 0 status = 0x340 [ 271.053386] xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x340 [ 271.053433] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 271.053441] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 271.053484] usb usb6-port1: not enabled, trying warm reset again... [ 271.153707] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 2 [ 271.153723] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling. [ 271.263105] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 271.263118] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 271.263184] usb usb6-port1: not warm reset yet, waiting 200ms [ 271.473137] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 271.473149] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 271.473219] usb usb6-port1: not warm reset yet, waiting 200ms [ 271.683168] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 271.683182] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 271.683335] usb usb6-port1: not warm reset yet, waiting 200ms [ 271.893207] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 271.893226] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 271.893384] usb usb6-port1: not warm reset yet, waiting 200ms [ 271.893445] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual port 0 status = 0x480340 [ 271.893587] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset change, actual port 0 status = 0x400340 [ 271.893664] xhci-hcd xhci-hcd.0.auto: clear port link state change, actual port 0 status = 0x340 [ 271.893718] xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x340 [ 271.893771] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 271.893780] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 271.893824] usb usb6-port1: not enabled, trying warm reset again... [ 271.993316] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 2 [ 271.993330] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling. [ 272.103108] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 272.103121] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 272.103190] usb usb6-port1: not warm reset yet, waiting 200ms [ 272.313107] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 272.313120] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 272.313193] usb usb6-port1: not warm reset yet, waiting 200ms [ 272.523123] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 272.523135] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 272.523205] usb usb6-port1: not warm reset yet, waiting 200ms [ 272.733109] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 272.733123] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 272.733193] usb usb6-port1: not warm reset yet, waiting 200ms [ 272.733217] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual port 0 status = 0x480340 [ 272.733279] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset change, actual port 0 status = 0x400340 [ 272.733328] xhci-hcd xhci-hcd.0.auto: clear port link state change, actual port 0 status = 0x340 [ 272.733378] xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x340 [ 272.733427] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 272.733436] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 272.733490] usb usb6-port1: not enabled, trying warm reset again... [ 272.773052] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping port polling. [ 272.833925] xhci-hcd xhci-hcd.0.auto: Port Status Change Event for port 2 [ 272.833941] xhci-hcd xhci-hcd.0.auto: handle_port_status: starting port polling. [ 272.943184] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 272.943197] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 272.943268] usb usb6-port1: not warm reset yet, waiting 200ms [ 273.153107] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2802e0 [ 273.153120] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x3002e0 [ 273.153202] usb usb6-port1: not warm reset yet, waiting 200ms [ 273.363110] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 273.363123] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 273.363206] usb usb6-port1: not warm reset yet, waiting 200ms [ 273.573105] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x680340 [ 273.573119] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x700340 [ 273.573188] usb usb6-port1: not warm reset yet, waiting 200ms [ 273.573210] xhci-hcd xhci-hcd.0.auto: clear port reset change, actual port 0 status = 0x480340 [ 273.573281] xhci-hcd xhci-hcd.0.auto: clear port warm(BH) reset change, actual port 0 status = 0x400340 [ 273.573336] xhci-hcd xhci-hcd.0.auto: clear port link state change, actual port 0 status = 0x340 [ 273.573388] xhci-hcd xhci-hcd.0.auto: clear port connect change, actual port 0 status = 0x340 [ 273.573438] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 273.573447] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 273.573491] usb usb6-port1: not enabled, trying warm reset again... [ 273.573498] usb usb6-port1: Cannot enable. Maybe the USB cable is bad? [ 273.603016] xhci-hcd xhci-hcd.0.auto: Cannot set link state. [ 273.633187] usb usb6-port1: cannot disable (err = -32) [ 273.661229] hub 6-0:1.0: state 7 ports 1 chg 0000 evt 0002 [ 273.661260] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x340 [ 273.661269] xhci-hcd xhci-hcd.0.auto: Get port status returned 0x340 [ 273.661333] usb usb6-port1: do warm reset [ 273.718125] xhci-hcd xhci-hcd.0.auto: get port status, actual port 0 status = 0x2b0 [ 273.718137] xhci-hcd xhci-hcd.0.auto: Get port status r ..... Thanks Patrice > > -Mathias > -- 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
