Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Schmid, Carsten]

[Resend - had mailer errors ]

Hi Florian,

today i have seen a strange behaviour of two D-Link DUB-1312 adapters (same Revision A1).
Plugging them into the same port (!) on my device one of them is recognized as SuperSpeed, the other as high speed ???
(working on 4.14.129 LTS)

From dmesg, the "faulty" one:
[  530.585871] usb 1-2: new high-speed USB device number 4 using xhci_hcd   <<<<<<<<< HUH ????
[  530.718872] usb 1-2: New USB device found, idVendor=2001, idProduct=4a00
[  530.718880] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  530.718885] usb 1-2: Product: D-Link DUB-1312
[  530.718889] usb 1-2: Manufacturer: D-Link Elec. Corp.
[  530.718893] usb 1-2: SerialNumber: 000000000024B9
[  531.055104] ax88179_178a 1-2:1.0 eth0: register 'ax88179_178a' at usb-0000:00:15.0-2, D-Link DUB-1312 USB 3.0 to Gigabit Ethernet Adapter, f4:8c:eb:4b:49:4e
[ 1151.424860] usb 1-2: USB disconnect, device number 4

And here comes the "good" one:
[ 1151.425110] ax88179_178a 1-2:1.0 eth0: unregister 'ax88179_178a' usb-0000:00:15.0-2, D-Link DUB-1312 USB 3.0 to Gigabit Ethernet Adapter
[ 1157.886447] usb 2-2: new SuperSpeed USB device number 4 using xhci_hcd <<<<<<<<<<< FINE !!!!
[ 1157.905885] usb 2-2: New USB device found, idVendor=2001, idProduct=4a00
[ 1157.905893] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1157.905898] usb 2-2: Product: D-Link DUB-1312
[ 1157.905902] usb 2-2: Manufacturer: D-Link Elec. Corp.
[ 1157.905906] usb 2-2: SerialNumber: 00000000000AF2
[ 1158.246076] ax88179_178a 2-2:1.0 eth0: register 'ax88179_178a' at usb-0000:00:15.0-2, D-Link DUB-1312 USB 3.0 to Gigabit Ethernet Adapter, 40:9b:cd:73:f1:f3

As you can see, same Vendor and Product ID.
(And really: it is the same connector i plugged it in!)

I had a look at the driver code of ax88179, but that one didn't change much in the past up to v5.2.
Nothing that explains what i can see here.

What can i do to dig deeper why this happens?

Best regards
Carsten

Re: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Oliver Neukum]

Am Mittwoch, den 14.08.2019, 08:17 +0000 schrieb  Schmid, Carsten :
> [Resend - had mailer errors ]
> 
> Hi Florian,
> 
> today i have seen a strange behaviour of two D-Link DUB-1312 adapters (same Revision A1).
> Plugging them into the same port (!) on my device one of them is recognized as SuperSpeed, the other as high speed ???
> (working on 4.14.129 LTS)
> 
> From dmesg, the "faulty" one:
> [  530.585871] usb 1-2: new high-speed USB device number 4 using xhci_hcd   <<<<<<<<< HUH ????

XHCI is not like EHCI. It needs no companion controller, as it serves
all speeds.

> I had a look at the driver code of ax88179, but that one didn't change much in the past up to v5.2.
> Nothing that explains what i can see here.

This is on a lower layer than ax88179. This comes from xhci_hcd.
Is this a regression?

	Regards
		Oliver

AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Schmid, Carsten]

>> Plugging them into the same port (!) on my device one of them is
>> recognized as SuperSpeed, the other as high speed ???
>> (working on 4.14.129 LTS)
>>
>> From dmesg, the "faulty" one:
>> [  530.585871] usb 1-2: new high-speed USB device number 4 using
>> xhci_hcd   <<<<<<<<< HUH ????
>> 
> XHCI is not like EHCI. It needs no companion controller, as it serves
> all speeds.
> 
...
> 
> This is on a lower layer than ax88179. This comes from xhci_hcd.
> Is this a regression?
> 
I don't think its a regression.

Meanwhile some more strange things:
Depending on how fast i plug in the "faulty" one, sometimes
it is recognized as a SuperSpeed too.
But then, i have made the following observation:
- ping from the device to a host works (and vice versa)
- scp-ing a file from host to to device the adapter suddenly stalls,
  but i don't see any error message in dmesg
- device then is stalled, ping doesn't work any more
- unbind/bind driver recovers the adapter
  (and always returns SuperSpeed mode)
- ping works, scp breaks it again
- leaving the device in stall, scp tells "lost connection"
  on the host after ~10 minutes

Is there something i can do to force an error message to be seen
when the ETH2USB adapter stalls?

My current assumption is that the signal quality of the USB port is at a
corner case, and therefore some "better" Adapters work, some "bad ones"
don't. But as there is no error message seen in the dmesg, i am somehow lost.

Best regards
Carsten

AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Schmid, Carsten]

>>> Plugging them into the same port (!) on my device one of them is
>>> recognized as SuperSpeed, the other as high speed ???
>>> (working on 4.14.129 LTS)
>>>
>>> From dmesg, the "faulty" one:
>>> [  530.585871] usb 1-2: new high-speed USB device number 4 using
>>> xhci_hcd   <<<<<<<<< HUH ????
>>>
>> XHCI is not like EHCI. It needs no companion controller, as it serves
>> all speeds.
>>
>> This is on a lower layer than ax88179. This comes from xhci_hcd.
>> Is this a regression?
>>
> I don't think its a regression.
>
I can see the same on a 4.14.102.

Next observation:
After some - long - time (> 15 minutes) a hanging ping
says:
ping: sendto: Network is unreachable

After this, without doing anything, i can start ping again
and it works:

$:~# ping 134.86.56.80
PING 134.86.56.80 (134.86.56.80): 56 data bytes
ping: sendto: Network is unreachable
$:~# ping 134.86.56.80
PING 134.86.56.80 (134.86.56.80): 56 data bytes
64 bytes from 134.86.56.80: seq=0 ttl=63 time=3.206 ms
64 bytes from 134.86.56.80: seq=1 ttl=63 time=0.662 ms

Looks like a higher rate of transfers causes a stall or retries
or whatever - but without any message i'm lost.
I can reproduce this 100%.

Someone there who has any advice what i can do to
track this down?

Best regards
Carsten

Re: AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Oliver Neukum]

Am Mittwoch, den 14.08.2019, 08:56 +0000 schrieb  Schmid, Carsten :

> > This is on a lower layer than ax88179. This comes from xhci_hcd.
> > Is this a regression?
> > 
> 
> I don't think its a regression.

It would be better to know than to assume.

> Is there something i can do to force an error message to be seen
> when the ETH2USB adapter stalls?

You can activate dynamic debugging for the xhci_hcd module
Remember that no data to transfer is not an error as such.

> My current assumption is that the signal quality of the USB port is at a
> corner case, and therefore some "better" Adapters work, some "bad ones"
> don't. But as there is no error message seen in the dmesg, i am somehow lost.

Two things you can do:

1. Generate a usbmon trace (it will be gigantic though)
2. Activate dynamic debugging for the xhci_hcd module


	Regards
		Oliver

AW: AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Schmid, Carsten]

>> I don't think its a regression.
>
> It would be better to know than to assume.
>
Happens with kernel 4.14.102 also, not only with 4.14.129.
Looks more HW related.

>
>> Is there something i can do to force an error message to be seen
>> when the ETH2USB adapter stalls?
>
> You can activate dynamic debugging for the xhci_hcd module
> Remember that no data to transfer is not an error as such.
>
>> My current assumption is that the signal quality of the USB port is at a
>> corner case, and therefore some "better" Adapters work, some "bad ones"
>> don't. But as there is no error message seen in the dmesg, i am somehow lost.
>
> Two things you can do:
>
> 1. Generate a usbmon trace (it will be gigantic though)
> 2. Activate dynamic debugging for the xhci_hcd module
I did:
echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control
echo -n 'usbcore =p' > /sys/kernel/debug/dynamic_debug/control
echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
(used this when hunting for another USB issue in the past also)

From traces/logs:
########################################
I can see in dmesg at a certain point, i assume this is where trouble starts:
[87800.393785] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.393869] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.393956] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.394045] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.394145] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.394216] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.394302] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.394385] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 15904 bytes untransferred
[87800.394587] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint
[87800.394596] xhci_hcd 0000:00:15.0: Cleaning up stalled endpoint ring
[87800.394600] xhci_hcd 0000:00:15.0: Finding endpoint context
[87800.394603] xhci_hcd 0000:00:15.0: Cycle state = 0x1
[87800.394606] xhci_hcd 0000:00:15.0: New dequeue segment = ffff8d9330b29900 (virtual)
[87800.394608] xhci_hcd 0000:00:15.0: New dequeue pointer = 0x174213400 (DMA)
[87800.394610] xhci_hcd 0000:00:15.0: Queueing new dequeue state
[87800.394613] xhci_hcd 0000:00:15.0: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b4213400 (0x174213400 dma), new cycle = 1
[87800.394618] xhci_hcd 0000:00:15.0: // Ding dong!
[87800.394622] xhci_hcd 0000:00:15.0: Giveback URB ffff8d931d65b600, len = 0, expected = 74, status = -71
[87800.394629] xhci_hcd 0000:00:15.0: Ignoring reset ep completion code of 1
[87800.394636] xhci_hcd 0000:00:15.0: Successful Set TR Deq Ptr cmd, deq = @174213400
[87800.394836] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.394916] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395005] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395090] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395178] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395263] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395350] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395436] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395525] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395613] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395710] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395785] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
[87800.395868] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 11328 bytes untransferred
[87800.398155] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint
[87800.398172] xhci_hcd 0000:00:15.0: Cleaning up stalled endpoint ring
[87800.398175] xhci_hcd 0000:00:15.0: Finding endpoint context
[87800.398179] xhci_hcd 0000:00:15.0: Cycle state = 0x1
[87800.398181] xhci_hcd 0000:00:15.0: New dequeue segment = ffff8d9330b29900 (virtual)
[87800.398184] xhci_hcd 0000:00:15.0: New dequeue pointer = 0x174213410 (DMA)
[87800.398186] xhci_hcd 0000:00:15.0: Queueing new dequeue state
[87800.398189] xhci_hcd 0000:00:15.0: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b4213410 (0x174213410 dma), new cycle = 1
[87800.398192] xhci_hcd 0000:00:15.0: // Ding dong!
[87800.398197] xhci_hcd 0000:00:15.0: Giveback URB ffff8d92b4374c00, len = 0, expected = 74, status = -71
[87800.398209] xhci_hcd 0000:00:15.0: Ignoring reset ep completion code of 1
[87800.398217] xhci_hcd 0000:00:15.0: Successful Set TR Deq Ptr cmd, deq = @174213410
[87800.401654] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint

These Transfer errors continue to happen, i think this is a massive slowdown then.

########################################
Trace shows around this timeframe:
          <idle>-0     [000] d.h2 87800.014500: xhci_queue_trb: CMD: Reset Endpoint Command: ctx 0000000000000000 slot 3 ep 6 flags C
          <idle>-0     [000] d.h2 87800.014502: xhci_inc_enq: CMD ffff8d92b40f3e00: enq 0x0000000174342c60(0x0000000174342000) deq 0x0000000174342c50(0x0000000174342000) segs 1 stream 0 free_trbs 253 bounce 0 cycle 1
          <idle>-0     [000] d.h2 87800.014510: xhci_dbg_reset_ep: Cleaning up stalled endpoint ring
          <idle>-0     [000] d.h2 87800.014517: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [000] d.h2 87800.014522: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [000] d.h2 87800.014531: xhci_dbg_cancel_urb: New dequeue segment = ffff8d9330b29900 (virtual)
          <idle>-0     [000] d.h2 87800.014537: xhci_dbg_cancel_urb: New dequeue pointer = 0x1742138c0 (DMA)
          <idle>-0     [000] d.h2 87800.014543: xhci_dbg_reset_ep: Queueing new dequeue state
          <idle>-0     [000] d.h2 87800.014550: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b42138c0 (0x1742138c0 dma), new cycle = 1
          <idle>-0     [000] d.h2 87800.014554: xhci_queue_trb: CMD: Set TR Dequeue Pointer Command: deq 00000001742138c1 stream 0 slot 3 ep 6 flags C
          <idle>-0     [000] d.h2 87800.014555: xhci_inc_enq: CMD ffff8d92b40f3e00: enq 0x0000000174342c70(0x0000000174342000) deq 0x0000000174342c50(0x0000000174342000) segs 1 stream 0 free_trbs 252 bounce 0 cycle 1
          <idle>-0     [000] d.h1 87800.014572: xhci_urb_giveback: ep3out-bulk: urb ffff8d92b4374180 pipe 3221324544 slot 3 length 0/470 sgs 0/0 stream 0 flags 00010000
          <idle>-0     [000] d.h2 87800.014583: xhci_handle_event: EVENT: TRB 0000000174342c50 status 'Success' len 0 slot 3 ep 0 type 'Command Completion Event' flags e:c
          <idle>-0     [000] d.h2 87800.014584: xhci_handle_command: CMD: Reset Endpoint Command: ctx 0000000000000000 slot 3 ep 6 flags C
          <idle>-0     [000] d.h2 87800.014587: xhci_handle_cmd_reset_ep: State stopped mult 1 max P. Streams 0 interval 125 us max ESIT payload 0 CErr 3 Type Bulk OUT burst 15 maxp 1024 deq 00000001742138c1 avg trb len 0
          <idle>-0     [000] d.h2 87800.014594: xhci_dbg_reset_ep: Ignoring reset ep completion code of 1
          <idle>-0     [000] d.h2 87800.014597: xhci_inc_deq: CMD ffff8d92b40f3e00: enq 0x0000000174342c70(0x0000000174342000) deq 0x0000000174342c60(0x0000000174342000) segs 1 stream 0 free_trbs 253 bounce 0 cycle 1
          <idle>-0     [000] d.h2 87800.014598: xhci_handle_event: EVENT: TRB 0000000174342c60 status 'Success' len 0 slot 3 ep 0 type 'Command Completion Event' flags e:c
          <idle>-0     [000] d.h2 87800.014599: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 00000001742138c1 stream 0 slot 3 ep 6 flags C
          <idle>-0     [000] d.h2 87800.014601: xhci_handle_cmd_set_deq: RS 00000 super-speed Ctx Entries 6 MEL 512 us Port# 10/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 3 State configured
          <idle>-0     [000] d.h2 87800.014602: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 0 interval 125 us max ESIT payload 0 CErr 3 Type Bulk OUT burst 15 maxp 1024 deq 00000001742138c1 avg trb len 0
          <idle>-0     [000] d.h2 87800.014608: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1742138c0
          <idle>-0     [000] d.h2 87800.014610: xhci_inc_deq: CMD ffff8d92b40f3e00: enq 0x0000000174342c70(0x0000000174342000) deq 0x0000000174342c70(0x0000000174342000) segs 1 stream 0 free_trbs 254 bounce 0 cycle 1
          <idle>-0     [000] dNh2 87800.139476: xhci_handle_event: EVENT: TRB 00000001cfa5a0f0 status 'Success' len 0 slot 3 ep 3 type 'Transfer Event' flags e:c
          <idle>-0     [000] dNh2 87800.139486: xhci_handle_transfer: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
          <idle>-0     [000] dNh2 87800.139490: xhci_inc_deq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a100(0x00000001cfa5a000) deq 0x00000001cfa5a100(0x00000001cfa5a000) segs 2 stream 0 free_trbs 509 bounce 8 cycle 1
          <idle>-0     [000] dNh1 87800.139496: xhci_urb_giveback: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 8/8 sgs 0/0 stream 0 flags 00010300
          <idle>-0     [000] dNh1 87800.139512: xhci_urb_enqueue: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 0/8 sgs 0/0 stream 0 flags 00010300
          <idle>-0     [000] dNh2 87800.139518: xhci_queue_trb: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
          <idle>-0     [000] dNh2 87800.139519: xhci_inc_enq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a110(0x00000001cfa5a000) deq 0x00000001cfa5a100(0x00000001cfa5a000) segs 2 stream 0 free_trbs 508 bounce 8 cycle 1
     AvbTxWrklow-271   [000] d.h1 87800.267463: xhci_handle_event: EVENT: TRB 00000001cfa5a100 status 'Success' len 0 slot 3 ep 3 type 'Transfer Event' flags e:c
     AvbTxWrklow-271   [000] d.h1 87800.267471: xhci_handle_transfer: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
     AvbTxWrklow-271   [000] d.h1 87800.267476: xhci_inc_deq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a110(0x00000001cfa5a000) deq 0x00000001cfa5a110(0x00000001cfa5a000) segs 2 stream 0 free_trbs 509 bounce 8 cycle 1
     AvbTxWrklow-271   [000] d.h. 87800.267480: xhci_urb_giveback: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 8/8 sgs 0/0 stream 0 flags 00010300
     AvbTxWrklow-271   [000] d.h. 87800.267494: xhci_urb_enqueue: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 0/8 sgs 0/0 stream 0 flags 00010300
     AvbTxWrklow-271   [000] d.h1 87800.267499: xhci_queue_trb: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
     AvbTxWrklow-271   [000] d.h1 87800.267500: xhci_inc_enq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a120(0x00000001cfa5a000) deq 0x00000001cfa5a110(0x00000001cfa5a000) segs 2 stream 0 free_trbs 508 bounce 8 cycle 1
          <idle>-0     [000] d.h2 87800.395533: xhci_handle_event: EVENT: TRB 00000001cfa5a110 status 'Success' len 0 slot 3 ep 3 type 'Transfer Event' flags e:c
          <idle>-0     [000] d.h2 87800.395543: xhci_handle_transfer: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
          <idle>-0     [000] d.h2 87800.395548: xhci_inc_deq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a120(0x00000001cfa5a000) deq 0x00000001cfa5a120(0x00000001cfa5a000) segs 2 stream 0 free_trbs 509 bounce 8 cycle 1
          <idle>-0     [000] d.h1 87800.395554: xhci_urb_giveback: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 8/8 sgs 0/0 stream 0 flags 00010300
          <idle>-0     [000] d.h1 87800.395570: xhci_urb_enqueue: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 0/8 sgs 0/0 stream 0 flags 00010300
          <idle>-0     [000] d.h2 87800.395575: xhci_queue_trb: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
          <idle>-0     [000] d.h2 87800.395576: xhci_inc_enq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a130(0x00000001cfa5a000) deq 0x00000001cfa5a120(0x00000001cfa5a000) segs 2 stream 0 free_trbs 508 bounce 8 cycle 1
          <idle>-0     [000] d.h2 87800.523536: xhci_handle_event: EVENT: TRB 00000001cfa5a120 status 'Success' len 0 slot 3 ep 3 type 'Transfer Event' flags e:c
          <idle>-0     [000] d.h2 87800.523546: xhci_handle_transfer: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
          <idle>-0     [000] d.h2 87800.523550: xhci_inc_deq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a130(0x00000001cfa5a000) deq 0x00000001cfa5a130(0x00000001cfa5a000) segs 2 stream 0 free_trbs 509 bounce 8 cycle 1
          <idle>-0     [000] d.h1 87800.523556: xhci_urb_giveback: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 8/8 sgs 0/0 stream 0 flags 00010300
          <idle>-0     [000] d.h1 87800.523571: xhci_urb_enqueue: ep1in-intr: urb ffff8d931fb43840 pipe 1073775488 slot 3 length 0/8 sgs 0/0 stream 0 flags 00010300
          <idle>-0     [000] d.h2 87800.523576: xhci_queue_trb: INTR: Buffer 00000001dfadbaa8 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
          <idle>-0     [000] d.h2 87800.523577: xhci_inc_enq: INTR ffff8d92b0edf380: enq 0x00000001cfa5a140(0x00000001cfa5a000) deq 0x00000001cfa5a130(0x00000001cfa5a000) segs 2 stream 0 free_trbs 508 bounce 8 cycle 1
....
     ksoftirqd/0-7     [000] d.s3 87801.459142: xhci_urb_enqueue: ep3out-bulk: urb ffff8d92965cd180 pipe 3221324544 slot 3 length 0/86 sgs 0/0 stream 0 flags 00010000
     ksoftirqd/0-7     [000] d.s4 87801.459146: xhci_queue_trb: BULK: Buffer 00000001565b18ba length 86 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:i:e:c
     ksoftirqd/0-7     [000] d.s4 87801.459147: xhci_inc_enq: BULK ffff8d92b0edf680: enq 0x00000001742138d0(0x0000000174213000) deq 0x00000001742138c0(0x0000000174213000) segs 2 stream 0 free_trbs 508 bounce 1024 cycle 1
          <idle>-0     [000] d.h2 87801.462490: xhci_handle_event: EVENT: TRB 00000001742138c0 status 'USB Transaction Error' len 86 slot 3 ep 6 type 'Transfer Event' flags e:c
          <idle>-0     [000] d.h2 87801.462518: xhci_handle_transfer: BULK: Buffer 00000001565b18ba length 86 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:i:e:C
          <idle>-0     [000] d.h2 87801.462534: xhci_queue_trb: CMD: Reset Endpoint Command: ctx 0000000000000000 slot 3 ep 6 flags C
          <idle>-0     [000] d.h2 87801.462536: xhci_inc_enq: CMD ffff8d92b40f3e00: enq 0x0000000174342c80(0x0000000174342000) deq 0x0000000174342c70(0x0000000174342000) segs 1 stream 0 free_trbs 253 bounce 0 cycle 1
          <idle>-0     [000] d.h2 87801.462545: xhci_dbg_reset_ep: Cleaning up stalled endpoint ring
          <idle>-0     [000] d.h2 87801.462551: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [000] d.h2 87801.462556: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [000] d.h2 87801.462562: xhci_dbg_cancel_urb: New dequeue segment = ffff8d9330b29900 (virtual)
          <idle>-0     [000] d.h2 87801.462567: xhci_dbg_cancel_urb: New dequeue pointer = 0x1742138d0 (DMA)
          <idle>-0     [000] d.h2 87801.462574: xhci_dbg_reset_ep: Queueing new dequeue state
          <idle>-0     [000] d.h2 87801.462581: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b42138d0 (0x1742138d0 dma), new cycle = 1


Really looks like this is a scenario where we have a device working with errors that can be recovered.
But because many errors are happening, it leads to a massive slowdown and finally a failure.
However, this takes a very long time, sometimes > 10 minutes.
And, because retries mostly work, we can't see errors in upper layers.

I'm not a USB expert, but maybe you can confirm this assumption?

Best regards
Carsten

AW: AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Schmid, Carsten]

> >> I don't think its a regression.
> >
> > It would be better to know than to assume.
> >
> Happens with kernel 4.14.102 also, not only with 4.14.129.
> Looks more HW related.
> 
Confirmed: HW issue.

Best regards
Carsten

Re: AW: AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Oliver Neukum]

Am Donnerstag, den 15.08.2019, 12:02 +0000 schrieb  Schmid, Carsten :
> > > I don't think its a regression.
> > 
> > It would be better to know than to assume.
> > 
> 
> Happens with kernel 4.14.102 also, not only with 4.14.129.
> Looks more HW related.
> 
> > 
> > > Is there something i can do to force an error message to be seen
> > > when the ETH2USB adapter stalls?
> > 
> > You can activate dynamic debugging for the xhci_hcd module
> > Remember that no data to transfer is not an error as such.
> > 
> > > My current assumption is that the signal quality of the USB port is at a
> > > corner case, and therefore some "better" Adapters work, some "bad ones"
> > > don't. But as there is no error message seen in the dmesg, i am somehow lost.
> > 
> > Two things you can do:
> > 
> > 1. Generate a usbmon trace (it will be gigantic though)
> > 2. Activate dynamic debugging for the xhci_hcd module
> 
> I did:
> echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control
> echo -n 'usbcore =p' > /sys/kernel/debug/dynamic_debug/control
> echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
> (used this when hunting for another USB issue in the past also)
> 
> From traces/logs:
> ########################################
> I can see in dmesg at a certain point, i assume this is where trouble starts:
> [87800.393785] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.393869] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.393956] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394045] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394145] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394216] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394302] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394385] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 15904 bytes untransferred
> [87800.394587] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint
> [87800.394596] xhci_hcd 0000:00:15.0: Cleaning up stalled endpoint ring
> [87800.394600] xhci_hcd 0000:00:15.0: Finding endpoint context
> [87800.394603] xhci_hcd 0000:00:15.0: Cycle state = 0x1
> [87800.394606] xhci_hcd 0000:00:15.0: New dequeue segment = ffff8d9330b29900 (virtual)
> [87800.394608] xhci_hcd 0000:00:15.0: New dequeue pointer = 0x174213400 (DMA)
> [87800.394610] xhci_hcd 0000:00:15.0: Queueing new dequeue state
> [87800.394613] xhci_hcd 0000:00:15.0: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b4213400 (0x174213400 dma), new cycle = 1
> [87800.394618] xhci_hcd 0000:00:15.0: // Ding dong!
> [87800.394622] xhci_hcd 0000:00:15.0: Giveback URB ffff8d931d65b600, len = 0, expected = 74, status = -71
> [87800.394629] xhci_hcd 0000:00:15.0: Ignoring reset ep completion code of 1
> [87800.394636] xhci_hcd 0000:00:15.0: Successful Set TR Deq Ptr cmd, deq = @174213400
> [87800.394836] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394916] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395005] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395090] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395178] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395263] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395350] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395436] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395525] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395613] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395710] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395785] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395868] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 11328 bytes untransferred
> [87800.398155] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint
> [87800.398172] xhci_hcd 0000:00:15.0: Cleaning up stalled endpoint ring
> [87800.398175] xhci_hcd 0000:00:15.0: Finding endpoint context
> [87800.398179] xhci_hcd 0000:00:15.0: Cycle state = 0x1
> [87800.398181] xhci_hcd 0000:00:15.0: New dequeue segment = ffff8d9330b29900 (virtual)
> [87800.398184] xhci_hcd 0000:00:15.0: New dequeue pointer = 0x174213410 (DMA)
> [87800.398186] xhci_hcd 0000:00:15.0: Queueing new dequeue state
> [87800.398189] xhci_hcd 0000:00:15.0: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b4213410 (0x174213410 dma), new cycle = 1
> [87800.398192] xhci_hcd 0000:00:15.0: // Ding dong!
> [87800.398197] xhci_hcd 0000:00:15.0: Giveback URB ffff8d92b4374c00, len = 0, expected = 74, status = -71
> [87800.398209] xhci_hcd 0000:00:15.0: Ignoring reset ep completion code of 1
> [87800.398217] xhci_hcd 0000:00:15.0: Successful Set TR Deq Ptr cmd, deq = @174213410
> [87800.401654] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint

This points at a low level XHCI thing. Time to get Mathias involved.

	Regards
		Oliver

AW: AW: AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

[Schmid, Carsten]

Hi all,

we had a look at the adapters, and it's really a HW issue.
Nothing we can follow up here anymore.

Let's close it.

Thanks!

Best regards
Carsten
________________________________________
Von: Oliver Neukum <oneukum@suse.com>
Gesendet: Montag, 19. August 2019 14:11
An: Schmid, Carsten; f.fainelli@gmail.com
Cc: linux-usb@vger.kernel.org; Mathias Nyman
Betreff: Re: AW: AW: Strange behaviour of D-Link DUB-1312 USB 3.0 Adapters

Am Donnerstag, den 15.08.2019, 12:02 +0000 schrieb  Schmid, Carsten :
> > > I don't think its a regression.
> >
> > It would be better to know than to assume.
> >
>
> Happens with kernel 4.14.102 also, not only with 4.14.129.
> Looks more HW related.
>
> >
> > > Is there something i can do to force an error message to be seen
> > > when the ETH2USB adapter stalls?
> >
> > You can activate dynamic debugging for the xhci_hcd module
> > Remember that no data to transfer is not an error as such.
> >
> > > My current assumption is that the signal quality of the USB port is at a
> > > corner case, and therefore some "better" Adapters work, some "bad ones"
> > > don't. But as there is no error message seen in the dmesg, i am somehow lost.
> >
> > Two things you can do:
> >
> > 1. Generate a usbmon trace (it will be gigantic though)
> > 2. Activate dynamic debugging for the xhci_hcd module
>
> I did:
> echo -n 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control
> echo -n 'usbcore =p' > /sys/kernel/debug/dynamic_debug/control
> echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
> (used this when hunting for another USB issue in the past also)
>
> From traces/logs:
> ########################################
> I can see in dmesg at a certain point, i assume this is where trouble starts:
> [87800.393785] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.393869] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.393956] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394045] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394145] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394216] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394302] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394385] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 15904 bytes untransferred
> [87800.394587] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint
> [87800.394596] xhci_hcd 0000:00:15.0: Cleaning up stalled endpoint ring
> [87800.394600] xhci_hcd 0000:00:15.0: Finding endpoint context
> [87800.394603] xhci_hcd 0000:00:15.0: Cycle state = 0x1
> [87800.394606] xhci_hcd 0000:00:15.0: New dequeue segment = ffff8d9330b29900 (virtual)
> [87800.394608] xhci_hcd 0000:00:15.0: New dequeue pointer = 0x174213400 (DMA)
> [87800.394610] xhci_hcd 0000:00:15.0: Queueing new dequeue state
> [87800.394613] xhci_hcd 0000:00:15.0: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b4213400 (0x174213400 dma), new cycle = 1
> [87800.394618] xhci_hcd 0000:00:15.0: // Ding dong!
> [87800.394622] xhci_hcd 0000:00:15.0: Giveback URB ffff8d931d65b600, len = 0, expected = 74, status = -71
> [87800.394629] xhci_hcd 0000:00:15.0: Ignoring reset ep completion code of 1
> [87800.394636] xhci_hcd 0000:00:15.0: Successful Set TR Deq Ptr cmd, deq = @174213400
> [87800.394836] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.394916] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395005] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395090] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395178] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395263] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395350] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395436] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395525] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395613] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395710] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395785] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 9808 bytes untransferred
> [87800.395868] xhci_hcd 0000:00:15.0: ep 0x82 - asked for 20480 bytes, 11328 bytes untransferred
> [87800.398155] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint
> [87800.398172] xhci_hcd 0000:00:15.0: Cleaning up stalled endpoint ring
> [87800.398175] xhci_hcd 0000:00:15.0: Finding endpoint context
> [87800.398179] xhci_hcd 0000:00:15.0: Cycle state = 0x1
> [87800.398181] xhci_hcd 0000:00:15.0: New dequeue segment = ffff8d9330b29900 (virtual)
> [87800.398184] xhci_hcd 0000:00:15.0: New dequeue pointer = 0x174213410 (DMA)
> [87800.398186] xhci_hcd 0000:00:15.0: Queueing new dequeue state
> [87800.398189] xhci_hcd 0000:00:15.0: Set TR Deq Ptr cmd, new deq seg = ffff8d9330b29900 (0x174213000 dma), new deq ptr = ffff8d92b4213410 (0x174213410 dma), new cycle = 1
> [87800.398192] xhci_hcd 0000:00:15.0: // Ding dong!
> [87800.398197] xhci_hcd 0000:00:15.0: Giveback URB ffff8d92b4374c00, len = 0, expected = 74, status = -71
> [87800.398209] xhci_hcd 0000:00:15.0: Ignoring reset ep completion code of 1
> [87800.398217] xhci_hcd 0000:00:15.0: Successful Set TR Deq Ptr cmd, deq = @174213410
> [87800.401654] xhci_hcd 0000:00:15.0: Transfer error for slot 3 ep 5 on endpoint

This points at a low level XHCI thing. Time to get Mathias involved.

        Regards
                Oliver