uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Tj (Elloe Linux)]

With all kernels from 4.14 to 5.8.0-rc5 we're seeing failures with uas
on a Turris Mox aarch64 Marvell Armada 3720 that we don't see on amd64.

The device that triggers them is:

Bus 003 Device 002: ID 152d:0562 JMicron Technology Corp. / JMicron USA
Technology Corp.

These are USB3<>NVME adapters with 256GB NVME attached.

On advice from the Turris Mox developers we tried booting with and
without "pci=nomsi".

We have other similar JMicron devices but they use usb-storage instead
and work fine.

Linked below is the complete output from dmesg, lspci -vvnnk, lsusb -v
but here's a snapshot of the error messages:

...
[   13.601433] hub 2-1:1.0: 4 ports detected
[   13.724437] usb 3-1: new SuperSpeed Gen 1 USB device number 2 using
xhci_hcd
[   13.784151] scsi host0: uas
[   13.788820] scsi 0:0:0:0: Direct-Access     JMicron  Tech
0204 PQ: 0 ANSI: 6
[   13.830081] sd 0:0:0:0: [sda] 500118192 512-byte logical blocks: (256
GB/238 GiB)
[   13.835692] sd 0:0:0:0: Attached scsi generic sg0 type 0
[   13.840597] sd 0:0:0:0: [sda] 4096-byte physical blocks
[   13.894211] sd 0:0:0:0: [sda] Write Protect is off
[   13.904097] sd 0:0:0:0: [sda] Mode Sense: 5f 00 00 08
[   13.907773] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   13.944550] sd 0:0:0:0: [sda] Optimal transfer size 33553920 bytes
not a multiple of physical block size (4096 bytes)
...
[   15.390872] sd 0:0:0:0: [sda] Attached SCSI disk
...
[   46.104025] sd 0:0:0:0: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6
inflight: IN
[   46.109072] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
d8 00 00 28 00
[   46.119512] sd 0:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 5
inflight: IN
[   46.124842] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x28 28 00 1d cf 2f
28 00 00 a8 00
[   46.152049] scsi host0: uas_eh_device_reset_handler start
[   46.285155] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using
xhci_hcd
[   46.312219] scsi host0: uas_eh_device_reset_handler success
[   76.827742] scsi host0: uas_eh_device_reset_handler start
[   76.831151] sd 0:0:0:0: [sda] tag#21 uas_zap_pending 0 uas-tag 1
inflight:
[   76.837629] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
d8 00 00 28 00
[   76.845513] sd 0:0:0:0: [sda] tag#20 uas_zap_pending 0 uas-tag 2
inflight:
[   76.852678] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x28 28 00 1d cf 2f
28 00 00 a8 00
[   76.992756] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using
xhci_hcd
...

If we try to read the device with, e.g:

$ sudo dd if=/dev/sda count=8 | hexdump -C

then we see I/O errors:

...
[  199.911106] blk_update_request: I/O error, dev sda, sector 500117288
op 0x0:(READ) flags 0x80700 phys_seg 21 prio class 0
[  199.922749] sd 0:0:0:0: [sda] tag#21 UNKNOWN(0x2003) Result:
hostbyte=0x08 driverbyte=0x00 cmd_age=184s
[  199.932074] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
d8 00 00 28 00
[  199.939976] blk_update_request: I/O error, dev sda, sector 500117464
op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0


For complete text of logs see https://elloe.vision/linux/  - logs are
available as text/plain and in a tar.gz archive.

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Greg KH]

On Sun, Jul 19, 2020 at 11:22:10AM +0100, Tj (Elloe Linux) wrote:
> With all kernels from 4.14 to 5.8.0-rc5 we're seeing failures with uas
> on a Turris Mox aarch64 Marvell Armada 3720 that we don't see on amd64.
> 
> The device that triggers them is:
> 
> Bus 003 Device 002: ID 152d:0562 JMicron Technology Corp. / JMicron USA
> Technology Corp.
> 
> These are USB3<>NVME adapters with 256GB NVME attached.
> 
> On advice from the Turris Mox developers we tried booting with and
> without "pci=nomsi".

That implies that the host controller, or the PCI controller code, is
not working on the arm system well?

> We have other similar JMicron devices but they use usb-storage instead
> and work fine.
> 
> Linked below is the complete output from dmesg, lspci -vvnnk, lsusb -v
> but here's a snapshot of the error messages:
> 
> ...
> [   13.601433] hub 2-1:1.0: 4 ports detected
> [   13.724437] usb 3-1: new SuperSpeed Gen 1 USB device number 2 using
> xhci_hcd
> [   13.784151] scsi host0: uas
> [   13.788820] scsi 0:0:0:0: Direct-Access     JMicron  Tech
> 0204 PQ: 0 ANSI: 6
> [   13.830081] sd 0:0:0:0: [sda] 500118192 512-byte logical blocks: (256
> GB/238 GiB)
> [   13.835692] sd 0:0:0:0: Attached scsi generic sg0 type 0
> [   13.840597] sd 0:0:0:0: [sda] 4096-byte physical blocks
> [   13.894211] sd 0:0:0:0: [sda] Write Protect is off
> [   13.904097] sd 0:0:0:0: [sda] Mode Sense: 5f 00 00 08
> [   13.907773] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
> enabled, doesn't support DPO or FUA
> [   13.944550] sd 0:0:0:0: [sda] Optimal transfer size 33553920 bytes
> not a multiple of physical block size (4096 bytes)
> ...
> [   15.390872] sd 0:0:0:0: [sda] Attached SCSI disk
> ...
> [   46.104025] sd 0:0:0:0: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6
> inflight: IN
> [   46.109072] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
> d8 00 00 28 00
> [   46.119512] sd 0:0:0:0: [sda] tag#20 uas_eh_abort_handler 0 uas-tag 5
> inflight: IN
> [   46.124842] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x28 28 00 1d cf 2f
> 28 00 00 a8 00
> [   46.152049] scsi host0: uas_eh_device_reset_handler start
> [   46.285155] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using
> xhci_hcd
> [   46.312219] scsi host0: uas_eh_device_reset_handler success
> [   76.827742] scsi host0: uas_eh_device_reset_handler start
> [   76.831151] sd 0:0:0:0: [sda] tag#21 uas_zap_pending 0 uas-tag 1
> inflight:
> [   76.837629] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
> d8 00 00 28 00
> [   76.845513] sd 0:0:0:0: [sda] tag#20 uas_zap_pending 0 uas-tag 2
> inflight:
> [   76.852678] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x28 28 00 1d cf 2f
> 28 00 00 a8 00
> [   76.992756] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using
> xhci_hcd
> ...

Where is an error here?  Those looks ok to me.

> If we try to read the device with, e.g:
> 
> $ sudo dd if=/dev/sda count=8 | hexdump -C
> 
> then we see I/O errors:
> 
> ...
> [  199.911106] blk_update_request: I/O error, dev sda, sector 500117288
> op 0x0:(READ) flags 0x80700 phys_seg 21 prio class 0
> [  199.922749] sd 0:0:0:0: [sda] tag#21 UNKNOWN(0x2003) Result:
> hostbyte=0x08 driverbyte=0x00 cmd_age=184s
> [  199.932074] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
> d8 00 00 28 00
> [  199.939976] blk_update_request: I/O error, dev sda, sector 500117464
> op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0

So only the block layer is reporting errors, not the USB layer?  Any usb
controller errors?

And what USB controller driver are you using here?

thanks,

greg k-h

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Tj (Elloe Linux)]

On 19/07/2020 12:09, Greg KH wrote:
> On Sun, Jul 19, 2020 at 11:22:10AM +0100, Tj (Elloe Linux) wrote:
>> With all kernels from 4.14 to 5.8.0-rc5 we're seeing failures with uas
>> on a Turris Mox aarch64 Marvell Armada 3720 that we don't see on amd64.
>>
>> The device that triggers them is:
>>
>> Bus 003 Device 002: ID 152d:0562 JMicron Technology Corp. / JMicron USA
>> Technology Corp.
>>
> 
> That implies that the host controller, or the PCI controller code, is
> not working on the arm system well?

With 5.8.0-rc5 we're seeing less errors (although devices are still
unusable) in the log than we see with the Turris Mox kernel v4.14.187
where there are many repeated 30 second timeouts of the form:

Jun  3 08:53:43 turris kernel: [ 1881.659833] scsi host0:
uas_eh_device_reset_handler success
Jun  3 08:53:51 turris kernel: [ 1889.671447] usb 3-1: cmd cmplt err -71
Jun  3 08:53:52 turris kernel: [ 1890.300858] usb 3-1: USB disconnect,
device number 3
Jun  3 08:53:52 turris kernel: [ 1890.307043] sd 0:0:0:0: tag#1
uas_zap_pending 0 uas-tag 2 inflight: CMD


>> [   46.152049] scsi host0: uas_eh_device_reset_handler start
>> [   46.285155] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using
>> xhci_hcd
>> [   46.312219] scsi host0: uas_eh_device_reset_handler success
>> [   76.827742] scsi host0: uas_eh_device_reset_handler start
>> [   76.831151] sd 0:0:0:0: [sda] tag#21 uas_zap_pending 0 uas-tag 1
>> inflight:
>> [   76.837629] sd 0:0:0:0: [sda] tag#21 CDB: opcode=0x28 28 00 1d cf 2f
>> d8 00 00 28 00
>> [   76.845513] sd 0:0:0:0: [sda] tag#20 uas_zap_pending 0 uas-tag 2
>> inflight:
>> [   76.852678] sd 0:0:0:0: [sda] tag#20 CDB: opcode=0x28 28 00 1d cf 2f
>> 28 00 00 a8 00
>> [   76.992756] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using
>> xhci_hcd
>> ...
> 
> Where is an error here?  Those looks ok to me.

These repeated 'zaps' and resets every 30 seconds or so are not errors?
They never stop even though the devices are not mounted nor being
accessed (by users).

>> [  199.939976] blk_update_request: I/O error, dev sda, sector 500117464
>> op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0
> 
> So only the block layer is reporting errors, not the USB layer?  Any usb
> controller errors?
> 
> And what USB controller driver are you using here?

From what I can deduce in sysfs it is xhci_hcd (note: same issue with 1
or 2 identical devices attached):

$ lsusb -d 152d:0562
Bus 003 Device 003: ID 152d:0562 JMicron Technology Corp. / JMicron USA
Technology Corp.
Bus 003 Device 002: ID 152d:0562 JMicron Technology Corp. / JMicron USA
Technology Corp.

$ ls -l  /sys/bus/usb/devices/3-{1,2}
lrwxrwxrwx 1 root root 0 Jul 19 09:19 /sys/bus/usb/devices/3-1 ->
../../../devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb3/3-1
lrwxrwxrwx 1 root root 0 Jul 19 12:27 /sys/bus/usb/devices/3-2 ->
../../../devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb3/3-2

$ lspci -nnk
00:00.0 PCI bridge [0604]: Marvell Technology Group Ltd. Device [1b4b:0100]
        Kernel driver in use: pcieport
01:00.0 USB controller [0c03]: VIA Technologies, Inc. VL805 USB 3.0 Host
Controller [1106:3483] (rev 01)
        Subsystem: VIA Technologies, Inc. VL805 USB 3.0 Host Controller
[1106:3483]
        Kernel driver in use: xhci_hcd
        Kernel modules: xhci_pci

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Alan Stern]

On Sun, Jul 19, 2020 at 11:22:10AM +0100, Tj (Elloe Linux) wrote:
> With all kernels from 4.14 to 5.8.0-rc5 we're seeing failures with uas
> on a Turris Mox aarch64 Marvell Armada 3720 that we don't see on amd64.
> 
> The device that triggers them is:
> 
> Bus 003 Device 002: ID 152d:0562 JMicron Technology Corp. / JMicron USA
> Technology Corp.
> 
> These are USB3<>NVME adapters with 256GB NVME attached.
> 
> On advice from the Turris Mox developers we tried booting with and
> without "pci=nomsi".
> 
> We have other similar JMicron devices but they use usb-storage instead
> and work fine.
> 
> Linked below is the complete output from dmesg, lspci -vvnnk, lsusb -v
> but here's a snapshot of the error messages:

Have you tried collecting a usbmon trace?  And in particular, have you 
tried comparing it with a usbmon trace collected on the AMD64 system?

Alan Stern

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Tj (Elloe Linux)]

On 19/07/2020 15:31, Alan Stern wrote:
> On Sun, Jul 19, 2020 at 11:22:10AM +0100, Tj (Elloe Linux) wrote:
>> With all kernels from 4.14 to 5.8.0-rc5 we're seeing failures with uas
>> on a Turris Mox aarch64 Marvell Armada 3720 that we don't see on amd64.
>>
>> The device that triggers them is:
>>
>> Bus 003 Device 002: ID 152d:0562 JMicron Technology Corp. / JMicron USA
>> Technology Corp.
>>
>> These are USB3<>NVME adapters with 256GB NVME attached.
>>
>> On advice from the Turris Mox developers we tried booting with and
>> without "pci=nomsi".
>>
>> We have other similar JMicron devices but they use usb-storage instead
>> and work fine.
>>
>> Linked below is the complete output from dmesg, lspci -vvnnk, lsusb -v
>> but here's a snapshot of the error messages:
> 
> Have you tried collecting a usbmon trace?  And in particular, have you 
> tried comparing it with a usbmon trace collected on the AMD64 system?
> 
> Alan Stern
> 
Not so far; We've just wrangled a Turris build system to build a vanilla
mainline kernel and Debian user-space. We'll tackle that this week.

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Oliver Neukum]

Am Sonntag, den 19.07.2020, 12:55 +0100 schrieb Tj (Elloe Linux):
> On 19/07/2020 12:09, Greg KH wrote:
> > On Sun, Jul 19, 2020 at 11:22:10AM +0100, Tj (Elloe Linux) wrote:

> > Where is an error here?  Those looks ok to me.
> 
> These repeated 'zaps' and resets every 30 seconds or so are not errors?

They are errors. But whose errors? 0x28 looks like a READ10 to me.
In other words at least Test Unit Ready and READ_CAPACITY have
already worked at this stage.
Without a trace it is not clear what exactly this read is for.
Is it always the same READ?

This looks like the error handling UAS does when a command times out.

> They never stop even though the devices are not mounted nor being
> accessed (by users).
> 
> > > [  199.939976] blk_update_request: I/O error, dev sda, sector 500117464
> > > op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0
> > 
> > So only the block layer is reporting errors, not the USB layer?  Any usb
> > controller errors?

The error is from the SCSI layer strictly speaking. It notices that a
command is taking longer than allowed and directs UAS to do error
handling. SUbsequently an error is reported up to the block layer.

The problem is that we have a lot of unusual stuff being tested.

	Regards
		Oliver

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Tj (Elloe Linux)]

On 20/07/2020 09:51, Oliver Neukum wrote:
>>
>> These repeated 'zaps' and resets every 30 seconds or so are not errors?
> 
> They are errors. But whose errors? 0x28 looks like a READ10 to me.
> In other words at least Test Unit Ready and READ_CAPACITY have
> already worked at this stage.
> Without a trace it is not clear what exactly this read is for.
> Is it always the same READ?
> 
> This looks like the error handling UAS does when a command times out.
> 
>> They never stop even though the devices are not mounted nor being
>> accessed (by users).
>>
>>>> [  199.939976] blk_update_request: I/O error, dev sda, sector 500117464
>>>> op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0
>>>
>>> So only the block layer is reporting errors, not the USB layer?  Any usb
>>> controller errors?
> 
> The error is from the SCSI layer strictly speaking. It notices that a
> command is taking longer than allowed and directs UAS to do error
> handling. SUbsequently an error is reported up to the block layer.
> 
> The problem is that we have a lot of unusual stuff being tested.

I've just built a kernel with more debugging options enabled and will
find time later today to install and test.

We have limited windows of time to test due to the Mox being our primary
gateway but I've ordered another Mox A (the main CPU module) so we can
test at will.

I'll update with the additional logs later.

Our Mox has maximum additional modules connected (they're named A
through G). The main CPU module (A) has its own USB3 port (presumably
via the SoC) but we're using the 4x USB3 module (F) which, I think, uses
a separate PCIe controller.

In our earlier tests the module A USB3 port wasn't active presumably
because we missed off a config option. Once we're corrected that we'll
test on the SoC USB3 port to help narrow down the responsible kernel
module(s) and layers.

https://www.turris.com/en/mox/modules/

Re: uas: bug: [sda] tag#21 uas_eh_abort_handler 0 uas-tag 6 inflight: IN

[Tj (Elloe Linux)]

On 20/07/2020 09:51, Oliver Neukum wrote:
> Am Sonntag, den 19.07.2020, 12:55 +0100 schrieb Tj (Elloe Linux):
>> On 19/07/2020 12:09, Greg KH wrote:
>>> On Sun, Jul 19, 2020 at 11:22:10AM +0100, Tj (Elloe Linux) wrote:
> 
>>> Where is an error here?  Those looks ok to me.
>>
>> These repeated 'zaps' and resets every 30 seconds or so are not errors?
> 
> They are errors. But whose errors? 0x28 looks like a READ10 to me.

Update for today: setting a quirk to not use UAS allows the device to
work without any apparent failures.

usb-storage.quirks=0x152d:0x0562:u

I plan on capturing a USB debug log with and without the
quirk tomorrow.

Re: uas: bug: [turris-L1 #1096031] MOX Hardware Issue - USB SuperSpeed ports resetting constantly

[Tj (Elloe Linux)]

On 20/07/2020 11:25, Tj (Elloe Linux) wrote:
> We have limited windows of time to test due to the Mox being our primary
> gateway but I've ordered another Mox A (the main CPU module) so we can> test at will.

We now have the second Mox A CPU module with USB3 module F attached in
our lab and can do any tests required.

# lspci -nn
00:00.0 PCI bridge [0604]: Marvell Technology Group Ltd. Device [1b4b:0100]
01:00.0 USB controller [0c03]: VIA Technologies, Inc. VL805 USB 3.0 Host
Controller [1106:3483] (rev 01)

> I'll update with the additional logs later.

I've captured a couple of usbmon logs, firstly when uas is enabled, and
then with it disabled via the quirk "0x152d:0x0562:u", and included the
associated dmesg logs.

They're available as text/plain and in a tar.gz with names prefixed
jmicron+ dated 2020-07-26 at:

https://elloe.vision/linux/

> In our earlier tests the module A USB3 port wasn't active presumably
> because we missed off a config option. Once we're corrected that we'll
> test on the SoC USB3 port to help narrow down the responsible kernel
> module(s) and layers.

It's currently not possible to test on the CPU module's USB3 since it
fails to initialise due to a fight between the firmware and OS because
in recent kernels the OS tries to initialise the PHY layer - but that is
already done by firmware. We've tested a suggested fix for that in uboot
but so far not made progress on that one.