Re: [xhci] usb 4-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd

From: Sedat Dilek
Date: Fri Mar 12 2021 - 12:03:36 EST


On Fri, Mar 12, 2021 at 5:57 PM Sedat Dilek <sedat.dilek@xxxxxxxxx> wrote:
>
> On Sun, Mar 7, 2021 at 6:07 PM Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> >
> > On Sun, Mar 07, 2021 at 05:57:39PM +0100, Sedat Dilek wrote:
> > > On Sun, Mar 7, 2021 at 4:46 PM Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> > > >
> > > > On Sat, Mar 06, 2021 at 09:49:00PM +0100, Sedat Dilek wrote:
> > > >
> > > > > For testing purposes, I stopped these systemd services:
> > > > >
> > > > > 1. systemctl stop smartmontools.service
> > > > >
> > > > > 2. systemctl stop udisks2.service
> > > > >
> > > > > Last seen xhci-reset:
> > > > >
> > > > > [Sat Mar 6 21:37:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > >
> > > > > So, that every 10min xhci-reset was caused by pool-udisksd from udisks2.service.
> > > >
> > > > You have found the cause of your problem! Great!
> > > >
> > > > And now, obviously order to fix the problem, you'll have to look into
> > > > the udisks2 service. Maybe you can configure it so that it won't send
> > > > the problem-causing commands.
> > > >
> > >
> > > I tried yesterday to add --debug option to the ExexStart line of
> > > udisks2.service, but did not see anything helpful.
> > >
> > > There exist more user-space than udisks2 causing these xhci-resets.
> > > The cmd#s are also clear: A1 and 85 - whatever they mean.
> >
> > Those are the two prefixes which indicate an ATA command is present.
> > You can find them listed as ATA_12 and ATA_16 in
> > include/scsi/scsi_proto.h.
> >
> > > As said with Linux v5.10.y and Linux v5.11 I have not seen this.
> >
> > Have you tried setting the quirk flag we discussed earlier _and_ turning
> > off udisks2? Maybe also turning off the other services which generate
> > these commands? Perhaps you'll find that when the quirk flag is
> > present, some of those programs _don't_ generate any ATA commands.
> >
>
> I passed as a kernel-command-line parameter: usb-storage.quirks=174c:55aa:t
>
> dmesg says:
>
> [Fri Mar 12 17:25:33 2021] usb-storage 4-1:1.0: Quirks match for vid
> 174c pid 55aa: 2400000
>
> Without that parameter (there is an existing Quirks for my ASMedia USB
> 3.0 controller in the kernel-sources):
>
> [Fri Mar 12 11:49:03 2021] usb-storage 4-1:1.0: Quirks match for vid
> 174c pid 55aa: 400000
>
> NOTE: 2400000 (new) VS. 400000 (old)
>
> The parameter is really active:
>
> root# cat /sys/module/usb_storage/parameters/quirks
> 174c:55aa:t
>
> The total number of xhci-resets is reduced:
>
> root# LC_ALL=C dmesg -T | egrep 'usb 4-1: reset SuperSpeed Gen 1 USB
> device number 2 using xhci_hcd' | wc -l
> 24
>
> Together with your diff, I see in dmesg now:
>
> # LC_ALL=C dmesg -T | egrep 'reset|SCSI ioctl error'
> [Fri Mar 12 17:25:32 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:25:32 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:25:33 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:33 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:33 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:34 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:34 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:34 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:34 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:34 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:35 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:35 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:35 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:35 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:36 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:36 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:36 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:25:36 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:36 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:38 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:38 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:38 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 12 17:25:58 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:25:58 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:03 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:26:05 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:06 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:07 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:07 2021] SCSI ioctl error, cmd 85, prog smartd
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Fri Mar 12 17:26:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:14 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:14 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:18 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:23 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:23 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:23 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:23 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:26:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:27:37 2021] SCSI ioctl error, cmd 85, prog smartctl
> [Fri Mar 12 17:27:37 2021] SCSI ioctl error, cmd 85, prog smartctl
> [Fri Mar 12 17:27:39 2021] SCSI ioctl error, cmd 85, prog smartctl
> [Fri Mar 12 17:27:40 2021] SCSI ioctl error, cmd 85, prog smartctl
> [Fri Mar 12 17:36:23 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:23 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:36:24 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:33 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:38:34 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:57 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:58 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:58 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:58 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:58 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Fri Mar 12 17:40:58 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
>
> So, the quirk you recommended seems to silence the xhci-resets -
> passed as a kernel-command-line parameter.
>
> Furthermore, I tried via:
>
> #1: /etc/modules-load.d/usb-storage.conf
> options usb-storage quirks=174c:55aa:t
>
> Should this be with a dot than a space?
> options usb-storage.quirks=174c:55aa:t
>

Grrr, space is right - I need to do an update-initramfs.

- Sedat -

> #2: echo '174c:55aa:t' > /sys/module/usb_storage/parameters/quirks
> ...after system was booted into
>
> Both had no effect.
>
> After 31mins of uptime I still see above 24 xhci-resets.
>
> I have attached my linux-config and full dmesg-log.
>
> - Sedat -