On Mon, 16 Apr 2018, Mathias Nyman wrote: > On 16.04.2018 13:20, Tushar Nimkar wrote: > > On 2018-04-05 11:31, Felipe Balbi wrote: > >> Hi, > >> > >> it would help if you would Cc XHCI's maintainer :-) > >> > >> tnimkar@xxxxxxxxxxxxxx writes: > >> > >>> On 2018-04-04 19:28, Greg KH wrote: > >>>> On Wed, Apr 04, 2018 at 06:41:41PM +0530, tnimkar@xxxxxxxxxxxxxx wrote: > >>>>> On 2018-04-04 18:07, Greg KH wrote: > >>>>> > On Wed, Apr 04, 2018 at 05:14:50PM +0530, tnimkar@xxxxxxxxxxxxxx wrote: > >>>>> > > Hi Oliver/Greg, > >>>>> > > > >>>>> > > I am able to duplicated the UAS issue on 4.16 as well. > >>>>> > > The behavior is same new usb device detects and reset after aprox 30 > >>>>> > > sec(SD_TIMEOUT) > >>>>> > > Logs are already shared below. > >>>>> > > > >>>>> > > We are using Synopsys dwc3 as host controller, May I know have > >>>>> > > tested it > >>>>> > > with dwc3? > >>>>> > > I have tried it on Linux PC (x86 Ubuntu machine) I could not see the > >>>>> > > issue. > >>>>> > > It enumerates well. > >>>>> > > >>>>> > Great, stick with an x86 platform! :) > >>>>> > > >>>>> > Looks like a dwc3 host controller issue, try enabling tracing and > >>>>> > debugging in that driver when this happens to see what is going on. > >>>>> > >>>>> Oh if so let me enable the trace for that. I will respond you on this. > >>> > >>> I did not get much clue, Greg. sometime this device enumerates well, > >>> attached both working and non working case logs. > >>> following is not working case > >>> root@OpenWrt:/# dmesg > > ... > > >>> [57214.172683] xhci-hcd xhci-hcd.0.auto: ep 0x83 - asked for 112 bytes, > >>> 96 bytes untransferred > >>> [57214.172809] xhci-hcd xhci-hcd.0.auto: ep 0x83 - asked for 112 bytes, > >>> 96 bytes untransferred > >>> [57214.172840] sd 1:0:0:0: [sdb] 976773168 512-byte logical blocks: (500 > >>> GB/466 GiB) > >>> [57214.172843] xhci-hcd xhci-hcd.0.auto: ep 0x81 - asked for 4096 bytes, > >>> 4080 bytes untransferred > >>> [57214.172851] xhci-hcd xhci-hcd.0.auto: ep 0x83 - asked for 112 bytes, > >>> 96 bytes untransferred > >>> [57214.253085] xhci-hcd xhci-hcd.0.auto: xhci_hub_status_data: stopping > >>> port polling. > > Huge gap before uas_eh_abort_eh_handler is called. This 30-second gap is typical for mass-storage. It's the default length of time before the higher layers give up on a request and tell the driver to cancel it. > >>> [57246.701096] sd 1:0:0:0: tag#0 uas_eh_abort_handler 0 uas-tag 1 > >>> inflight: CMD IN > >>> [57246.701130] sd 1:0:0:0: tag#0 CDB: opcode=0x1a 1a 00 3f 00 04 00 > > URB is canceled, maybe that URB never finished? No doubt. Perhaps the device doesn't support this particular command. > >>> [57246.707583] xhci-hcd xhci-hcd.0.auto: Cancel URB 0000000007b523f0, > >>> dev 1, ep 0x81, starting at offset 0 > >>> [57246.707594] xhci-hcd xhci-hcd.0.auto: // Ding dong! > >>> [57246.707616] xhci-hcd xhci-hcd.0.auto: Stopped on No-op or Link TRB > >>> for slot 1 ep 2 > >>> [57246.707625] xhci-hcd xhci-hcd.0.auto: Removing canceled TD starting > >>> at 0x7f0cd0a0 (dma). > >>> [57246.707630] xhci-hcd xhci-hcd.0.auto: Finding endpoint context > >>> [57246.707634] xhci-hcd xhci-hcd.0.auto: Cycle state = 0x1 > >>> [57246.707637] xhci-hcd xhci-hcd.0.auto: New dequeue segment = > >>> 00000000890c7dc4 (virtual) > >>> [57246.707641] xhci-hcd xhci-hcd.0.auto: New dequeue pointer = > >>> 0x7f0cd0b0 (DMA) > >>> [57246.707646] xhci-hcd xhci-hcd.0.auto: Set TR Deq Ptr cmd, new deq seg > >>> = 00000000890c7dc4 (0x7f0cd000 dmeq ptr = 000000000ce7faa0 (0x7f0cd0b0 > >>> dma), new cycle = 1 > >>> [57246.707651] xhci-hcd xhci-hcd.0.auto: // Ding dong! > >>> [57246.707671] xhci-hcd xhci-hcd.0.auto: Successful Set TR Deq Ptr cmd, > >>> deq = @7f0cd0b0 > >>> [57246.721090] scsi host1: uas_eh_device_reset_handler start > >>> [57246.721114] xhci-hcd xhci-hcd.0.auto: Cancel URB 00000000279f06a2, > >>> dev 1, ep 0x83, starting at offset 0 > >>> [57246.721120] xhci-hcd xhci-hcd.0.auto: // Ding dong! > >>> [57246.721135] xhci-hcd xhci-hcd.0.auto: ERROR Transfer event for > >>> unknown stream ring slot 1 ep 6 > >>> [57246.725463] xhci-hcd xhci-hcd.0.auto: @000000007f044780 00000000 > >>> 00000000 1b000000 01078001 > > Stop -Length invalid transfer event. That is normal when canceling a URB, > but it should point to the TRB xhc was working on when stopped. > Here it just points to 0. That part looks like some issue with this specific > controller. > > Some other errors may return 0 as their TRB pointer, but not this event. > > But this is not the cause, just a detail while handling the real cause. > Nothing in this log shows why the URB was canceled in the first place. Presumably because the URB never completed, and therefore the transfer timed out and was cancelled by the SCSI layer. Alan Stern > usbmon and xhci traces could help, xhci traces: > > mount -t debugfs none /sys/kernel/debug > echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb > echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable > > then send /sys/kernel/debug/tracing/trace after issue triggered. > > -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 > > -- 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
