Re: uas failing on multiple disk access on a jmicron JMS567 bridge

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



> 
>> On 22 May 2017, at 14:37, Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx> wrote:
>> 
>> On 22.05.2017 11:48, Christoph Gohle wrote:
>>> Hey Mathias,
>>> 
>>> 
>>>> On 19 May 2017, at 09:58, Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx> wrote:
>>>> 
>>>>> 
>>>> 
>>>> 4.11 kernel has xhci traces enabled, could you try to reproduce it with 4.11?
>>>> xhci traces can be enabled with:
>>>> 
>>>> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
>>>> 
>>>> If you know how to reliably reproduce this then please enable tracing just before
>>>> triggering this. It generates a lot of data.
>>>> 
>>>> -Mathias
>>> I would be able to do xhci traces with a 4.10 kernel (4.10.0-21-generic #23~16.04.1-Ubuntu SMP). Don’t really want to go to 4.11. . Still interested?
>> 
>> xhci got more useful tracing support in 4.11,
>> Sure, you can try if there's something in 4.10
OK. Now I managed (had to update-initramfs, stupid…)

So I triggered the failiure with xhci-hcd tracing enabled. I can’t make much sense out of the trace. Maybe you can? The trace is as follows (I removed repeating ‘Removing canceled TD...':


# tracer: nop
#
# entries-in-buffer/entries-written: 1536/1536   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
 device 1 sectio-3419  [002] d...   326.179876: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x209e5c320
          <idle>-0     [002] d.h.   326.179952: xhci_cmd_completion:
trb_dma=@26e01a820, trb_va=@ffff8dcc6e01a820, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   326.179959: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x209e5c320 (dma).
.
.
.
          <idle>-0     [002] d.h.   326.180141: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x209e5c710 (dma).
 device 1 sectio-3419  [002] d...   326.180198: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x209e5c720
          <idle>-0     [002] d.h.   326.180243: xhci_cmd_completion:
trb_dma=@26e01a830, trb_va=@ffff8dcc6e01a830, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   326.180248: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x209e5c720 (dma).
.
.
.
          <idle>-0     [002] d.h.   326.180420: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x209e5cb10 (dma).
 device 1 sectio-3419  [002] d...   326.180465: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x1ebb11730
          <idle>-0     [002] d.h.   326.180504: xhci_cmd_completion:
trb_dma=@26e01a840, trb_va=@ffff8dcc6e01a840, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   326.180507: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11730 (dma).
          <idle>-0     [002] d.h.   326.180511: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   326.180515: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   326.180517: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcc040c7b40 (virtual)
          <idle>-0     [002] d.h.   326.180523: xhci_dbg_cancel_urb: New dequeue pointer = 0x1ebb11740 (DMA)
          <idle>-0     [002] d.h.   326.180528: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11740 (dma).
.
.
.
          <idle>-0     [002] d.h.   326.180697: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11b00 (dma).
          <idle>-0     [002] d.h.   326.180700: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcc040c7b40 (0x1ebb11000 dma), new deq ptr = ffff8dcbebb11740 (0x1ebb11740 dma), new cycle = 1
          <idle>-0     [002] dNh.   326.180738: xhci_cmd_completion:
trb_dma=@26e01a850, trb_va=@ffff8dcc6e01a850, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   326.180741: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1ebb11740
 device 1 sectio-3419  [002] d...   326.180847: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x1ebb11b10
          <idle>-0     [003] d.H.   326.180918: xhci_cmd_completion:
trb_dma=@26e01a860, trb_va=@ffff8dcc6e01a860, status=01000000, flags=04008400
          <idle>-0     [003] d.H.   326.180924: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11b10 (dma).
          <idle>-0     [003] d.H.   326.180931: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [003] d.H.   326.180936: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [003] d.H.   326.180941: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcc040c7b40 (virtual)
          <idle>-0     [003] d.H.   326.180945: xhci_dbg_cancel_urb: New dequeue pointer = 0x1ebb11b20 (DMA)
          <idle>-0     [003] d.H.   326.180948: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11b20 (dma).
.
.
.
          <idle>-0     [003] d.H.   326.181129: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11f00 (dma).
          <idle>-0     [003] d.H.   326.181132: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcc040c7b40 (0x1ebb11000 dma), new deq ptr = ffff8dcbebb11b20 (0x1ebb11b20 dma), new cycle = 1
          <idle>-0     [003] d.H.   326.181188: xhci_cmd_completion:
trb_dma=@26e01a870, trb_va=@ffff8dcc6e01a870, status=01000000, flags=04008400
          <idle>-0     [003] d.H.   326.181191: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1ebb11b20
 device 1 sectio-3419  [002] d...   326.181205: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x1ebb11f10
          <idle>-0     [002] d.h.   326.181247: xhci_cmd_completion:
trb_dma=@26e01a880, trb_va=@ffff8dcc6e01a880, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   326.181252: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb11f10 (dma).
.
.
.
           <idle>-0     [002] d.h.   326.181435: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x209e5c310 (dma).
          <idle>-0     [002] d.h.   327.288291: xhci_cmd_completion:
trb_dma=@26e01a890, trb_va=@ffff8dcc6e01a890, status=01000000, flags=04008401
 device 1 sectio-3419  [002] ....   327.288342: xhci_dbg_context_change: Successful Endpoint Configure command
          <idle>-0     [002] d.h.   327.313000: xhci_dbg_ring_expansion: ERROR no room on ep ring, try ring expansion
          <idle>-0     [002] d.h.   327.313045: xhci_dbg_ring_expansion: ring expansion succeed, now has 4 segments
 device 1 sectio-3419  [000] d...   347.177471: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x20eb42f00
          <idle>-0     [002] dNh.   347.177530: xhci_cmd_completion:
trb_dma=@26e01a8a0, trb_va=@ffff8dcc6e01a8a0, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   347.177538: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42f00 (dma).
.
.
.
          <idle>-0     [002] dNh.   347.177660: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x2549c9300 (dma).
 device 1 sectio-3419  [000] d...   347.177897: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x26d92ef40
          <idle>-0     [002] dNh.   347.177953: xhci_cmd_completion:
trb_dma=@26e01a8b0, trb_va=@ffff8dcc6e01a8b0, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   347.177957: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d92ef50 (dma).
          <idle>-0     [002] dNh.   347.177961: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] dNh.   347.177962: xhci_dbg_cancel_urb: Cycle state = 0x0
          <idle>-0     [002] dNh.   347.177964: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbdefeee00 (virtual)
          <idle>-0     [002] dNh.   347.177968: xhci_dbg_cancel_urb: New dequeue pointer = 0x26d92ef60 (DMA)
          <idle>-0     [002] dNh.   347.177970: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d92ef60 (dma).
.
.
.
           <idle>-0     [002] dNh.   347.178075: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb422f0 (dma).
          <idle>-0     [002] dNh.   347.178078: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbdefeee00 (0x26d92e000 dma), new deq ptr = ffff8dcc6d92ef60 (0x26d92ef60 dma), new cycle = 0
          <idle>-0     [002] dNh.   347.178102: xhci_cmd_completion:
trb_dma=@26e01a8c0, trb_va=@ffff8dcc6e01a8c0, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   347.178104: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @26d92ef60
 device 1 sectio-3419  [000] d...   347.178242: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x20eb42300
          <idle>-0     [002] d.h.   347.178295: xhci_cmd_completion:
trb_dma=@26e01a8d0, trb_va=@ffff8dcc6e01a8d0, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   347.178298: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42300 (dma).
          <idle>-0     [002] d.h.   347.178302: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   347.178306: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   347.178308: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbdefeef80 (virtual)
          <idle>-0     [002] d.h.   347.178310: xhci_dbg_cancel_urb: New dequeue pointer = 0x20eb42310 (DMA)
          <idle>-0     [002] d.h.   347.178312: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42310 (dma).
.
.
.
          <idle>-0     [002] d.h.   347.178429: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb426f0 (dma).
          <idle>-0     [002] d.h.   347.178432: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbdefeef80 (0x20eb42000 dma), new deq ptr = ffff8dcc0eb42310 (0x20eb42310 dma), new cycle = 1
          <idle>-0     [002] dNh.   347.178465: xhci_cmd_completion:
trb_dma=@26e01a8e0, trb_va=@ffff8dcc6e01a8e0, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   347.178468: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @20eb42310
 device 1 sectio-3419  [000] d...   347.178595: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x20eb42700
          <idle>-0     [002] d.h.   347.178641: xhci_cmd_completion:
trb_dma=@26e01a8f0, trb_va=@ffff8dcc6e01a8f0, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   347.178644: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42700 (dma).
          <idle>-0     [002] d.h.   347.178647: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   347.178651: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   347.178653: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbdefeef80 (virtual)
          <idle>-0     [002] d.h.   347.178655: xhci_dbg_cancel_urb: New dequeue pointer = 0x20eb42710 (DMA)
          <idle>-0     [002] d.h.   347.178657: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42710 (dma).
.
.
.
          <idle>-0     [002] d.h.   347.178774: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42af0 (dma).
          <idle>-0     [002] d.h.   347.178776: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbdefeef80 (0x20eb42000 dma), new deq ptr = ffff8dcc0eb42710 (0x20eb42710 dma), new cycle = 1
          <idle>-0     [002] dNh.   347.178820: xhci_cmd_completion:
trb_dma=@26e01a900, trb_va=@ffff8dcc6e01a900, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   347.178822: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @20eb42710
 device 1 sectio-3419  [000] d...   347.178936: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x20eb42b00
          <idle>-0     [002] d.h.   347.178994: xhci_cmd_completion:
trb_dma=@26e01a910, trb_va=@ffff8dcc6e01a910, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   347.178997: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42b00 (dma).
          <idle>-0     [002] d.h.   347.179001: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   347.179004: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   347.179009: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbdefeef80 (virtual)
          <idle>-0     [002] d.h.   347.179011: xhci_dbg_cancel_urb: New dequeue pointer = 0x20eb42b10 (DMA)
          <idle>-0     [002] d.h.   347.179013: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42b10 (dma).
.
.
.
          <idle>-0     [002] d.h.   347.179130: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x20eb42ef0 (dma).
          <idle>-0     [002] d.h.   347.179132: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbdefeef80 (0x20eb42000 dma), new deq ptr = ffff8dcc0eb42b10 (0x20eb42b10 dma), new cycle = 1
          <idle>-0     [002] dNh.   347.179177: xhci_cmd_completion:
trb_dma=@26e01a920, trb_va=@ffff8dcc6e01a920, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   347.179179: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @20eb42b10
          <idle>-0     [002] d.h.   348.287092: xhci_cmd_completion:
trb_dma=@26e01a930, trb_va=@ffff8dcc6e01a930, status=01000000, flags=04008401
 device 1 sectio-3419  [000] ....   348.287299: xhci_dbg_context_change: Successful Endpoint Configure command
          <idle>-0     [002] d.h.   348.312308: xhci_dbg_ring_expansion: ERROR no room on ep ring, try ring expansion
          <idle>-0     [002] d.h.   348.312385: xhci_dbg_ring_expansion: ring expansion succeed, now has 4 segments
    kworker/u8:5-234   [000] d...   355.356495: xhci_dbg_cancel_urb: Cancel URB ffff8dcc759950c0, dev 2, ep 0x83, starting at offset 0x26da57540
          <idle>-0     [003] d.h.   355.356547: xhci_cmd_completion:
trb_dma=@26e01a940, trb_va=@ffff8dcc6e01a940, status=01000000, flags=02008401
          <idle>-0     [003] d.h.   355.356561: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da57540 (dma).
          <idle>-0     [003] d.h.   355.356571: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [003] d.h.   355.356576: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [003] d.h.   355.356579: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcc6da4a780 (virtual)
          <idle>-0     [003] d.h.   355.356585: xhci_dbg_cancel_urb: New dequeue pointer = 0x26da57740 (DMA)
          <idle>-0     [003] d.h.   355.356590: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcc6da4a780 (0x26da57000 dma), new deq ptr = ffff8dcc6da57740 (0x26da57740 dma), new cycle = 1
          <idle>-0     [003] dNh.   355.356656: xhci_cmd_completion:
trb_dma=@26e01a950, trb_va=@ffff8dcc6e01a950, status=01000000, flags=02008401
          <idle>-0     [003] dNh.   355.356661: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @26da57740
    kworker/u8:5-234   [003] d...   355.356797: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5aceacc0, dev 2, ep 0x83, starting at offset 0x26d99b220
          <idle>-0     [002] d.h.   355.356865: xhci_cmd_completion:
trb_dma=@26e01a960, trb_va=@ffff8dcc6e01a960, status=01000000, flags=02008401
          <idle>-0     [002] d.h.   355.356872: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d99b220 (dma).
    kworker/u8:5-234   [002] d...   355.357006: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86e540, dev 2, ep 0x83, starting at offset 0x26da53500
          <idle>-0     [002] d.h.   355.357059: xhci_cmd_completion:
trb_dma=@26e01a970, trb_va=@ffff8dcc6e01a970, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   355.357063: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da53500 (dma).
       scsi_eh_2-231   [002] d...   357.392425: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86ea80, dev 2, ep 0x4, starting at offset 0x26e350e90
       scsi_eh_2-231   [002] d.h.   357.392470: xhci_cmd_completion:
trb_dma=@26e01a980, trb_va=@ffff8dcc6e01a980, status=13000000, flags=02008401
       scsi_eh_2-231   [002] d.h.   357.392474: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26e350e90 (dma).
       scsi_eh_2-231   [002] d...   357.392549: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86e840, dev 2, ep 0x82, starting at offset 0x26d9d0190
       scsi_eh_2-231   [002] d.h.   357.392582: xhci_cmd_completion:
trb_dma=@26e01a990, trb_va=@ffff8dcc6e01a990, status=01000000, flags=02008401
       scsi_eh_2-231   [002] d.h.   357.392588: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9d0190 (dma).
       scsi_eh_2-231   [002] d.h.   357.392592: xhci_dbg_cancel_urb: Finding endpoint context
       scsi_eh_2-231   [002] d.h.   357.392599: xhci_dbg_cancel_urb: Cycle state = 0x1
       scsi_eh_2-231   [002] d.h.   357.392602: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcc6d93f780 (virtual)
       scsi_eh_2-231   [002] d.h.   357.392606: xhci_dbg_cancel_urb: New dequeue pointer = 0x26d9d01a0 (DMA)
       scsi_eh_2-231   [002] d.h.   357.392613: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcc6d93f780 (0x26d9d0000 dma), new deq ptr = ffff8dcc6d9d01a0 (0x26d9d01a0 dma), new cycle = 1
       scsi_eh_2-231   [002] d.h.   357.392637: xhci_cmd_completion:
trb_dma=@26e01a9a0, trb_va=@ffff8dcc6e01a9a0, status=01000000, flags=02008401
       scsi_eh_2-231   [002] d.h.   357.392642: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @26d9d01a0
       scsi_eh_2-231   [002] d...   357.392673: xhci_dbg_cancel_urb: Cancel URB ffff8dcc596770c0, dev 2, ep 0x82, starting at offset 0x26da40570
          <idle>-0     [003] d.h.   357.392779: xhci_cmd_completion:
trb_dma=@26e01a9b0, trb_va=@ffff8dcc6e01a9b0, status=01000000, flags=02008401
          <idle>-0     [003] d.h.   357.392786: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da40570 (dma).
       scsi_eh_2-231   [002] d...   357.392846: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5aceac00, dev 2, ep 0x82, starting at offset 0x26da5e2f0
          <idle>-0     [002] d.h.   357.392892: xhci_cmd_completion:
trb_dma=@26e01a9c0, trb_va=@ffff8dcc6e01a9c0, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.392897: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da5e2f0 (dma).
       scsi_eh_2-231   [002] d...   357.392962: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acead80, dev 2, ep 0x82, starting at offset 0x26da3e570
          <idle>-0     [002] d.h.   357.393002: xhci_cmd_completion:
trb_dma=@26e01a9d0, trb_va=@ffff8dcc6e01a9d0, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.393007: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da3e570 (dma).
       scsi_eh_2-231   [002] d...   357.393047: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea180, dev 2, ep 0x82, starting at offset 0x26d9d7650
          <idle>-0     [003] d.h.   357.393197: xhci_cmd_completion:
trb_dma=@26e01a9e0, trb_va=@ffff8dcc6e01a9e0, status=01000000, flags=02008400
          <idle>-0     [003] d.h.   357.393208: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9d7650 (dma).
       scsi_eh_2-231   [002] d...   357.393266: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea540, dev 2, ep 0x82, starting at offset 0x26d9ce1f0
          <idle>-0     [002] d.h.   357.393304: xhci_cmd_completion:
trb_dma=@26e01a9f0, trb_va=@ffff8dcc6e01a9f0, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.393309: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9ce1f0 (dma).
       scsi_eh_2-231   [002] d...   357.393364: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea300, dev 2, ep 0x82, starting at offset 0x26da47450
          <idle>-0     [002] d.h.   357.393402: xhci_cmd_completion:
trb_dma=@26e01aa00, trb_va=@ffff8dcc6e01aa00, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.393407: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da47450 (dma).
       scsi_eh_2-231   [002] d...   357.393469: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5aceaa80, dev 2, ep 0x82, starting at offset 0x26da49430
          <idle>-0     [003] d.h.   357.393637: xhci_cmd_completion:
trb_dma=@26e01aa10, trb_va=@ffff8dcc6e01aa10, status=01000000, flags=02008400
          <idle>-0     [003] d.h.   357.393648: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da49430 (dma).
       scsi_eh_2-231   [002] d...   357.393704: xhci_dbg_cancel_urb: Cancel URB ffff8dcc59677300, dev 2, ep 0x82, starting at offset 0x26d9d5b80
          <idle>-0     [002] d.h.   357.393742: xhci_cmd_completion:
trb_dma=@26e01aa20, trb_va=@ffff8dcc6e01aa20, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.393746: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9d5b80 (dma).
       scsi_eh_2-231   [002] d...   357.393788: xhci_dbg_cancel_urb: Cancel URB ffff8dcc59677840, dev 2, ep 0x82, starting at offset 0x26d9d3e70
          <idle>-0     [002] d.h.   357.393824: xhci_cmd_completion:
trb_dma=@26e01aa30, trb_va=@ffff8dcc6e01aa30, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.393829: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9d3e70 (dma).
       scsi_eh_2-231   [002] d...   357.393882: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86eb40, dev 2, ep 0x82, starting at offset 0x26da60d60
          <idle>-0     [002] d.h.   357.393920: xhci_cmd_completion:
trb_dma=@26e01aa40, trb_va=@ffff8dcc6e01aa40, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.393931: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da60d60 (dma).
       scsi_eh_2-231   [002] d...   357.393988: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6ded3c00, dev 2, ep 0x82, starting at offset 0x26da45470
          <idle>-0     [003] d.h.   357.394092: xhci_cmd_completion:
trb_dma=@26e01aa50, trb_va=@ffff8dcc6e01aa50, status=01000000, flags=02008400
          <idle>-0     [003] d.h.   357.394098: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da45470 (dma).
       scsi_eh_2-231   [002] d...   357.394164: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86ef00, dev 2, ep 0x82, starting at offset 0x26da43480
          <idle>-0     [002] d.h.   357.394206: xhci_cmd_completion:
trb_dma=@26e01aa60, trb_va=@ffff8dcc6e01aa60, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.394212: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26da43480 (dma).
       scsi_eh_2-231   [002] d...   357.394263: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86e600, dev 2, ep 0x82, starting at offset 0x26d9d1eb0
          <idle>-0     [002] d.h.   357.394306: xhci_cmd_completion:
trb_dma=@26e01aa70, trb_va=@ffff8dcc6e01aa70, status=01000000, flags=02008400
          <idle>-0     [002] d.h.   357.394310: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9d1eb0 (dma).
       scsi_eh_2-231   [002] d...   357.394370: xhci_dbg_cancel_urb: Cancel URB ffff8dcc59677240, dev 2, ep 0x4, starting at offset 0x26e26b9d0
          <idle>-0     [002] d.h.   357.394409: xhci_cmd_completion:
trb_dma=@26e01aa80, trb_va=@ffff8dcc6e01aa80, status=13000000, flags=02008400
          <idle>-0     [002] d.h.   357.394418: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26e26b9d0 (dma).
       scsi_eh_2-231   [002] d...   357.394476: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea240, dev 2, ep 0x4, starting at offset 0x26d9af310
          <idle>-0     [003] d.h.   357.394675: xhci_cmd_completion:
trb_dma=@26e01aa90, trb_va=@ffff8dcc6e01aa90, status=13000000, flags=02008400
          <idle>-0     [003] d.h.   357.394682: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9af310 (dma).
       scsi_eh_2-231   [002] d...   357.394742: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5aceaf00, dev 2, ep 0x4, starting at offset 0x26e357e70
          <idle>-0     [002] d.h.   357.394787: xhci_cmd_completion:
trb_dma=@26e01aaa0, trb_va=@ffff8dcc6e01aaa0, status=13000000, flags=02008400
          <idle>-0     [002] d.h.   357.394793: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26e357e70 (dma).
       scsi_eh_2-231   [002] d...   357.394846: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea6c0, dev 2, ep 0x4, starting at offset 0x26d9b37a0
          <idle>-0     [002] d.h.   357.394883: xhci_cmd_completion:
trb_dma=@26e01aab0, trb_va=@ffff8dcc6e01aab0, status=13000000, flags=02008400
          <idle>-0     [002] d.h.   357.394886: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26d9b37a0 (dma).
       scsi_eh_2-231   [002] d...   357.394928: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea900, dev 2, ep 0x4, starting at offset 0x1ebb17240
       scsi_eh_2-231   [002] d.h.   357.394954: xhci_cmd_completion:
trb_dma=@26e01aac0, trb_va=@ffff8dcc6e01aac0, status=13000000, flags=02008400
       scsi_eh_2-231   [002] d.h.   357.394960: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb17240 (dma).
       scsi_eh_2-231   [002] d...   357.394999: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5acea480, dev 2, ep 0x4, starting at offset 0x1ebb34e50
          <idle>-0     [003] d.h.   357.395045: xhci_cmd_completion:
trb_dma=@26e01aad0, trb_va=@ffff8dcc6e01aad0, status=13000000, flags=02008400
          <idle>-0     [003] d.h.   357.395050: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb34e50 (dma).
       scsi_eh_2-231   [002] d...   357.395129: xhci_dbg_cancel_urb: Cancel URB ffff8dcc59677780, dev 2, ep 0x4, starting at offset 0x26e333700
          mopidy-5773  [002] d.h.   357.395177: xhci_cmd_completion:
trb_dma=@26e01aae0, trb_va=@ffff8dcc6e01aae0, status=13000000, flags=02008400
          mopidy-5773  [002] d.h.   357.395183: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26e333700 (dma).
       scsi_eh_2-231   [002] d...   357.395266: xhci_dbg_cancel_urb: Cancel URB ffff8dcc59677cc0, dev 2, ep 0x4, starting at offset 0x26e267590
          mopidy-5773  [002] d.h.   357.395307: xhci_cmd_completion:
trb_dma=@26e01aaf0, trb_va=@ffff8dcc6e01aaf0, status=13000000, flags=02008400
          mopidy-5773  [002] d.h.   357.395312: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x26e267590 (dma).
       scsi_eh_2-231   [002] d...   357.395378: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6ded3240, dev 2, ep 0x4, starting at offset 0x1ebb505e0
          mopidy-5773  [002] d.h.   357.395417: xhci_cmd_completion:
trb_dma=@26e01ab00, trb_va=@ffff8dcc6e01ab00, status=13000000, flags=02008400
          mopidy-5773  [002] d.h.   357.395424: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb505e0 (dma).
       scsi_eh_2-231   [002] d...   357.395480: xhci_dbg_cancel_urb: Cancel URB ffff8dcc5a86e780, dev 2, ep 0x4, starting at offset 0x1ebb681b0
          <idle>-0     [003] d.h.   357.395565: xhci_cmd_completion:
trb_dma=@26e01ab10, trb_va=@ffff8dcc6e01ab10, status=13000000, flags=02008400
          <idle>-0     [003] d.h.   357.395573: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb681b0 (dma).
       in:imklog-3272  [002] d.h.   357.396744: xhci_cmd_completion:
trb_dma=@26e01ab20, trb_va=@ffff8dcc6e01ab20, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.396790: xhci_dbg_context_change: Successful Endpoint Configure command
       scsi_eh_2-231   [002] ....   357.397837: xhci_dbg_context_change: Set up evaluate context for LPM MEL change.
       in:imklog-3272  [002] d.h.   357.397874: xhci_cmd_completion:
trb_dma=@26e01ab30, trb_va=@ffff8dcc6e01ab30, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.397903: xhci_dbg_context_change: Successful evaluate context command
       rcu_sched-7     [003] d.h.   357.516327: xhci_cmd_completion:
trb_dma=@26e01ab40, trb_va=@ffff8dcc6e01ab40, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.516384: xhci_address_ctx:
ctx_64=0, ctx_type=2, ctx_dma=@26e1ed000, ctx_va=@ffff8dcc6e1ed000
          <idle>-0     [002] d.h.   357.516442: xhci_cmd_completion:
trb_dma=@26e01ab50, trb_va=@ffff8dcc6e01ab50, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.516482: xhci_dbg_address: Successful setup address command
       scsi_eh_2-231   [002] ....   357.516495: xhci_dbg_address: Op regs DCBAA ptr = 0x0000026e019000
       scsi_eh_2-231   [002] ....   357.516505: xhci_dbg_address: Slot ID 2 dcbaa entry @ffff8dcc6e019010 = 0x0000026e1de000
       scsi_eh_2-231   [002] ....   357.516513: xhci_dbg_address: Output Context DMA address = 0x26e1de000
       scsi_eh_2-231   [002] ....   357.516523: xhci_address_ctx:
ctx_64=0, ctx_type=2, ctx_dma=@26e1ed000, ctx_va=@ffff8dcc6e1ed000
       scsi_eh_2-231   [002] ....   357.516527: xhci_address_ctx:
ctx_64=0, ctx_type=1, ctx_dma=@26e1de000, ctx_va=@ffff8dcc6e1de000
       scsi_eh_2-231   [002] ....   357.516528: xhci_dbg_address: Internal device address = 2
          <idle>-0     [003] d.h.   357.537947: xhci_cmd_completion:
trb_dma=@26e01ab60, trb_va=@ffff8dcc6e01ab60, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.537989: xhci_dbg_context_change: Successful Endpoint Configure command
          <idle>-0     [002] d.h.   357.538530: xhci_cmd_completion:
trb_dma=@26e01ab70, trb_va=@ffff8dcc6e01ab70, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.538582: xhci_dbg_context_change: Successful Endpoint Configure command
       scsi_eh_2-231   [002] ....   357.538963: xhci_dbg_context_change: Set up evaluate context for LPM MEL change.
          <idle>-0     [003] d.h.   357.539002: xhci_cmd_completion:
trb_dma=@26e01ab80, trb_va=@ffff8dcc6e01ab80, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.539039: xhci_dbg_context_change: Successful evaluate context command
       scsi_eh_2-231   [002] ....   357.539351: xhci_dbg_context_change: Set up evaluate context for LPM MEL change.
          <idle>-0     [003] d.h.   357.539454: xhci_cmd_completion:
trb_dma=@26e01ab90, trb_va=@ffff8dcc6e01ab90, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.539495: xhci_dbg_context_change: Successful evaluate context command
       scsi_eh_2-231   [002] ....   357.541030: xhci_dbg_context_change: Setting number of stream ctx array entries to 32
       scsi_eh_2-231   [002] ....   357.541042: xhci_dbg_context_change: Setting number of stream ctx array entries to 32
       scsi_eh_2-231   [002] ....   357.541045: xhci_dbg_context_change: Setting number of stream ctx array entries to 32
          <idle>-0     [003] d.h.   357.541353: xhci_cmd_completion:
trb_dma=@26e01aba0, trb_va=@ffff8dcc6e01aba0, status=01000000, flags=02008400
       scsi_eh_2-231   [002] ....   357.541389: xhci_dbg_context_change: Successful Endpoint Configure command
 device 1 sectio-3419  [002] d...   368.184484: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x1ebb0df00
 device 1 sectio-3419  [002] d.h.   368.184539: xhci_cmd_completion:
trb_dma=@26e01abb0, trb_va=@ffff8dcc6e01abb0, status=01000000, flags=04008400
 device 1 sectio-3419  [002] d.h.   368.184545: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0df00 (dma).
.
.
.
 device 1 sectio-3419  [002] d.h.   368.184828: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x213968300 (dma).
 device 1 sectio-3419  [002] d...   368.184871: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x213968310
          <idle>-0     [002] d.h.   368.184920: xhci_cmd_completion:
trb_dma=@26e01abc0, trb_va=@ffff8dcc6e01abc0, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   368.184924: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x213968310 (dma).
.
.
.
          <idle>-0     [002] d.h.   368.185233: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x213968700 (dma).
 device 1 sectio-3419  [002] d...   368.185316: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x1ebb0d320
          <idle>-0     [002] d.h.   368.185366: xhci_cmd_completion:
trb_dma=@26e01abd0, trb_va=@ffff8dcc6e01abd0, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   368.185370: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0d320 (dma).
          <idle>-0     [002] d.h.   368.185375: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   368.185380: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   368.185387: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbde530980 (virtual)
          <idle>-0     [002] d.h.   368.185391: xhci_dbg_cancel_urb: New dequeue pointer = 0x1ebb0d330 (DMA)
          <idle>-0     [002] d.h.   368.185394: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0d330 (dma).
.
.
.
          <idle>-0     [002] d.h.   368.185663: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0d6f0 (dma).
          <idle>-0     [002] d.h.   368.185669: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbde530980 (0x1ebb0d000 dma), new deq ptr = ffff8dcbebb0d330 (0x1ebb0d330 dma), new cycle = 1
          <idle>-0     [002] dNh.   368.185716: xhci_cmd_completion:
trb_dma=@26e01abe0, trb_va=@ffff8dcc6e01abe0, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   368.185720: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1ebb0d330
 device 1 sectio-3419  [002] d...   368.185774: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x1ebb0d700
          <idle>-0     [003] d.h.   368.185893: xhci_cmd_completion:
trb_dma=@26e01abf0, trb_va=@ffff8dcc6e01abf0, status=01000000, flags=04008400
          <idle>-0     [003] d.h.   368.185899: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0d700 (dma).
          <idle>-0     [003] d.h.   368.185907: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [003] d.h.   368.185916: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [003] d.h.   368.185921: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbde530980 (virtual)
          <idle>-0     [003] d.h.   368.185928: xhci_dbg_cancel_urb: New dequeue pointer = 0x1ebb0d710 (DMA)
          <idle>-0     [003] d.h.   368.185931: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0d710 (dma).
.
.
.
          <idle>-0     [003] d.h.   368.186192: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0daf0 (dma).
          <idle>-0     [003] d.h.   368.186197: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbde530980 (0x1ebb0d000 dma), new deq ptr = ffff8dcbebb0d710 (0x1ebb0d710 dma), new cycle = 1
 device 1 sectio-3419  [002] d...   368.186266: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x1ebb0db00
          <idle>-0     [003] dNh.   368.186289: xhci_cmd_completion:
trb_dma=@26e01ac00, trb_va=@ffff8dcc6e01ac00, status=01000000, flags=04008400
          <idle>-0     [003] dNh.   368.186295: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1ebb0d710
          <idle>-0     [003] dNh.   368.186309: xhci_cmd_completion:
trb_dma=@26e01ac10, trb_va=@ffff8dcc6e01ac10, status=13000000, flags=04008400
          <idle>-0     [003] dNh.   368.186314: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0db00 (dma).
.
.
.
          <idle>-0     [003] dNh.   368.186569: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1ebb0def0 (dma).
          <idle>-0     [002] d.h.   369.294121: xhci_cmd_completion:
trb_dma=@26e01ac20, trb_va=@ffff8dcc6e01ac20, status=01000000, flags=04008401
 device 1 sectio-3419  [002] ....   369.294178: xhci_dbg_context_change: Successful Endpoint Configure command
          <idle>-0     [002] dNh.   369.318878: xhci_dbg_ring_expansion: ERROR no room on ep ring, try ring expansion
          <idle>-0     [002] dNh.   369.318941: xhci_dbg_ring_expansion: ring expansion succeed, now has 4 segments
 device 1 sectio-3419  [002] d...   389.255045: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x1f6e22330
 device 1 sectio-3419  [002] d.h.   389.255092: xhci_cmd_completion:
trb_dma=@26e01ac30, trb_va=@ffff8dcc6e01ac30, status=01000000, flags=04008401
 device 1 sectio-3419  [002] d.h.   389.255096: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22340 (dma).
 device 1 sectio-3419  [002] d.h.   389.255105: xhci_dbg_cancel_urb: Finding endpoint context
 device 1 sectio-3419  [002] d.h.   389.255108: xhci_dbg_cancel_urb: Cycle state = 0x1
 device 1 sectio-3419  [002] d.h.   389.255111: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbe159a140 (virtual)
 device 1 sectio-3419  [002] d.h.   389.255115: xhci_dbg_cancel_urb: New dequeue pointer = 0x1f6e22350 (DMA)
 device 1 sectio-3419  [002] d.h.   389.255118: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22350 (dma).
.
.
.
 device 1 sectio-3419  [002] d.h.   389.255395: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22710 (dma).
 device 1 sectio-3419  [002] d.h.   389.255405: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbe159a140 (0x1f6e22000 dma), new deq ptr = ffff8dcbf6e22350 (0x1f6e22350 dma), new cycle = 1
 device 1 sectio-3419  [002] d.h.   389.255443: xhci_cmd_completion:
trb_dma=@26e01ac40, trb_va=@ffff8dcc6e01ac40, status=01000000, flags=04008401
 device 1 sectio-3419  [002] d.h.   389.255446: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1f6e22350
 device 1 sectio-3419  [002] d...   389.255620: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x1f6e22720
          <idle>-0     [002] d.h.   389.255725: xhci_cmd_completion:
trb_dma=@26e01ac50, trb_va=@ffff8dcc6e01ac50, status=01000000, flags=04008401
          <idle>-0     [002] d.h.   389.255734: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22720 (dma).
          <idle>-0     [002] d.h.   389.255740: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   389.255747: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   389.255751: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbe159a140 (virtual)
          <idle>-0     [002] d.h.   389.255755: xhci_dbg_cancel_urb: New dequeue pointer = 0x1f6e22730 (DMA)
          <idle>-0     [002] d.h.   389.255758: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22730 (dma).
.
.
.
          <idle>-0     [002] d.h.   389.256044: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22b10 (dma).
          <idle>-0     [002] d.h.   389.256048: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbe159a140 (0x1f6e22000 dma), new deq ptr = ffff8dcbf6e22730 (0x1f6e22730 dma), new cycle = 1
          <idle>-0     [002] dNh.   389.256102: xhci_cmd_completion:
trb_dma=@26e01ac60, trb_va=@ffff8dcc6e01ac60, status=01000000, flags=04008401
          <idle>-0     [002] dNh.   389.256106: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1f6e22730
 device 1 sectio-3419  [002] d...   389.256137: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x1f6e22b20
          <idle>-0     [002] d.h.   389.256187: xhci_cmd_completion:
trb_dma=@26e01ac70, trb_va=@ffff8dcc6e01ac70, status=01000000, flags=04008401
          <idle>-0     [002] d.h.   389.256190: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22b20 (dma).
.
.
.
          <idle>-0     [002] d.h.   389.256363: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22f10 (dma).
 device 1 sectio-3419  [002] d...   389.256408: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x1f6e22f20
          <idle>-0     [003] d.h.   389.256623: xhci_cmd_completion:
trb_dma=@26e01ac80, trb_va=@ffff8dcc6e01ac80, status=01000000, flags=04008400
          <idle>-0     [003] d.h.   389.256629: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22f20 (dma).
          <idle>-0     [003] d.h.   389.256636: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [003] d.h.   389.256645: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [003] d.h.   389.256649: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbe159a140 (virtual)
          <idle>-0     [003] d.h.   389.256653: xhci_dbg_cancel_urb: New dequeue pointer = 0x1f6e22f30 (DMA)
          <idle>-0     [003] d.h.   389.256662: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f6e22f30 (dma).
.
.
.
          <idle>-0     [003] d.h.   389.256841: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f4167320 (dma).
          <idle>-0     [003] d.h.   389.256846: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbe159a140 (0x1f6e22000 dma), new deq ptr = ffff8dcbf6e22f30 (0x1f6e22f30 dma), new cycle = 1
          <idle>-0     [003] d.h.   389.256894: xhci_cmd_completion:
trb_dma=@26e01ac90, trb_va=@ffff8dcc6e01ac90, status=01000000, flags=04008400
          <idle>-0     [003] d.h.   389.256898: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1f6e22f30
 device 1 sectio-3419  [002] d...   389.256913: xhci_dbg_cancel_urb: Cancel URB ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x1f4167330
          <idle>-0     [002] d.h.   389.257010: xhci_cmd_completion:
trb_dma=@26e01aca0, trb_va=@ffff8dcc6e01aca0, status=01000000, flags=04008400
          <idle>-0     [002] d.h.   389.257014: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f4167330 (dma).
          <idle>-0     [002] d.h.   389.257018: xhci_dbg_cancel_urb: Finding endpoint context
          <idle>-0     [002] d.h.   389.257024: xhci_dbg_cancel_urb: Cycle state = 0x1
          <idle>-0     [002] d.h.   389.257030: xhci_dbg_cancel_urb: New dequeue segment = ffff8dcbe159a440 (virtual)
          <idle>-0     [002] d.h.   389.257033: xhci_dbg_cancel_urb: New dequeue pointer = 0x1f4167340 (DMA)
          <idle>-0     [002] d.h.   389.257036: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f4167340 (dma).
.
.
.          <idle>-0     [002] d.h.   389.257232: xhci_dbg_cancel_urb: Removing canceled TD starting at 0x1f4167720 (dma).
          <idle>-0     [002] d.h.   389.257236: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = ffff8dcbe159a440 (0x1f4167000 dma), new deq ptr = ffff8dcbf4167340 (0x1f4167340 dma), new cycle = 1
          <idle>-0     [002] dNh.   389.257275: xhci_cmd_completion:
trb_dma=@26e01acb0, trb_va=@ffff8dcc6e01acb0, status=01000000, flags=04008400
          <idle>-0     [002] dNh.   389.257278: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @1f4167340
          <idle>-0     [002] d.h.   390.364871: xhci_cmd_completion:
trb_dma=@26e01acc0, trb_va=@ffff8dcc6e01acc0, status=01000000, flags=04008401
 device 1 sectio-3419  [002] ....   390.364947: xhci_dbg_context_change: Successful Endpoint Configure command
          <idle>-0     [002] d.h.   390.389754: xhci_dbg_ring_expansion: ERROR no room on ep ring, try ring expansion
          <idle>-0     [002] d.h.   390.389820: xhci_dbg_ring_expansion: ring expansion succeed, now has 4 segments

the accompaining kernel messages are:

May 24 20:34:11 gserv kernel: [  324.868069] xhci_hcd 0000:00:14.0: ERROR Transfer event for disabled endpoint or incorrect stream ring
May 24 20:34:11 gserv kernel: [  324.868193] xhci_hcd 0000:00:14.0: @000000026e01ce90 00000000 00000000 04000000 02088000
May 24 20:34:42 gserv kernel: [  355.356457] sd 2:0:0:0: [sdb] tag#12 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD IN
May 24 20:34:42 gserv kernel: [  355.356478] sd 2:0:0:0: [sdb] tag#12 CDB: Read(16) 88 00 00 00 00 00 74 e7 9f e0 00 00 01 00 00 00
May 24 20:34:42 gserv kernel: [  355.356763] sd 2:0:0:0: [sdb] tag#8 uas_eh_abort_handler 0 uas-tag 8 inflight: CMD IN
May 24 20:34:42 gserv kernel: [  355.356784] sd 2:0:0:0: [sdb] tag#8 CDB: Read(16) 88 00 00 00 00 00 74 e7 9e e0 00 00 01 00 00 00
May 24 20:34:42 gserv kernel: [  355.356970] sd 2:0:0:0: [sdb] tag#13 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD IN
May 24 20:34:42 gserv kernel: [  355.356989] sd 2:0:0:0: [sdb] tag#13 CDB: Read(16) 88 00 00 00 00 00 74 e7 9d e0 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.392211] sd 2:0:0:2: [sdd] tag#4 uas_eh_abort_handler 0 uas-tag 5 inflight: CMD OUT
May 24 20:34:44 gserv kernel: [  357.392233] sd 2:0:0:2: [sdd] tag#4 CDB: Write(16) 8a 00 00 00 00 00 e8 10 25 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.392535] scsi host2: uas_eh_bus_reset_handler start
May 24 20:34:44 gserv kernel: [  357.395671] sd 2:0:0:1: [sdc] tag#3 uas_zap_pending 0 uas-tag 1 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395693] sd 2:0:0:1: [sdc] tag#3 CDB: Write(16) 8a 00 00 00 00 00 e8 10 27 f8 00 00 02 00 00 00
May 24 20:34:44 gserv kernel: [  357.395714] sd 2:0:0:1: [sdc] tag#1 uas_zap_pending 0 uas-tag 3 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395726] sd 2:0:0:1: [sdc] tag#1 CDB: Write(16) 8a 00 00 00 00 00 e8 10 26 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395741] sd 2:0:0:1: [sdc] tag#6 uas_zap_pending 0 uas-tag 6 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395753] sd 2:0:0:1: [sdc] tag#6 CDB: Write(16) 8a 00 00 00 00 00 e8 10 24 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395771] sd 2:0:0:2: [sdd] tag#2 uas_zap_pending 0 uas-tag 7 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395783] sd 2:0:0:2: [sdd] tag#2 CDB: Write(16) 8a 00 00 00 00 00 e8 10 27 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395798] sd 2:0:0:2: [sdd] tag#9 uas_zap_pending 0 uas-tag 9 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395809] sd 2:0:0:2: [sdd] tag#9 CDB: Write(16) 8a 00 00 00 00 00 e8 10 2b f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395825] sd 2:0:0:2: [sdd] tag#11 uas_zap_pending 0 uas-tag 10 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395837] sd 2:0:0:2: [sdd] tag#11 CDB: Write(16) 8a 00 00 00 00 00 e8 10 2c f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395854] sd 2:0:0:1: [sdc] tag#10 uas_zap_pending 0 uas-tag 11 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395866] sd 2:0:0:1: [sdc] tag#10 CDB: Write(16) 8a 00 00 00 00 00 e8 10 23 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395881] sd 2:0:0:2: [sdd] tag#7 uas_zap_pending 0 uas-tag 12 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395893] sd 2:0:0:2: [sdd] tag#7 CDB: Write(16) 8a 00 00 00 00 00 e8 10 26 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.395908] sd 2:0:0:2: [sdd] tag#5 uas_zap_pending 0 uas-tag 13 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395919] sd 2:0:0:2: [sdd] tag#5 CDB: Write(16) 8a 00 00 00 00 00 e8 10 28 f8 00 00 03 00 00 00
May 24 20:34:44 gserv kernel: [  357.395937] sd 2:0:0:1: [sdc] tag#0 uas_zap_pending 0 uas-tag 14 inflight: CMD
May 24 20:34:44 gserv kernel: [  357.395948] sd 2:0:0:1: [sdc] tag#0 CDB: Write(16) 8a 00 00 00 00 00 e8 10 25 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.516558] usb 2-2: reset SuperSpeed USB device number 2 using xhci_hcd
May 24 20:34:44 gserv kernel: [  357.541482] scsi host2: uas_eh_bus_reset_handler success
May 24 20:34:44 gserv kernel: [  357.542678] sd 2:0:0:2: [sdd] tag#4 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK
May 24 20:34:44 gserv kernel: [  357.542720] sd 2:0:0:2: [sdd] tag#4 CDB: Write(16) 8a 00 00 00 00 00 e8 10 25 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [  357.542736] blk_update_request: I/O error, dev sdd, sector 3893372408
May 24 20:34:49 gserv kernel: [  363.136196] xhci_hcd 0000:00:14.0: ERROR Transfer event for disabled endpoint or incorrect stream ring
May 24 20:34:49 gserv kernel: [  363.136468] xhci_hcd 0000:00:14.0: @000000026e01cb00 00000000 00000000 04000000 02088001

…

does that tell anything?

Cheers,
Christoph
--
Christoph Gohle
christoph@xxxxxxxxx






Attachment: signature.asc
Description: Message signed with OpenPGP using GPGMail


[Index of Archives]     [Linux Media]     [Linux Input]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [Old Linux USB Devel Archive]

  Powered by Linux