2021-02-24 17:28:00

by Sedat Dilek

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

On Wed, Feb 24, 2021 at 2:44 PM Sedat Dilek <[email protected]> wrote:
>
> Hi Mathias,
>
> I am here on Linux-v5.11-10201-gc03c21ba6f4e.
>
> I see a lot xhci-resets in my dmesg-log:
>
> root# LC_ALL=C dmesg -T | grep 'usb 4-1: reset SuperSpeed Gen 1 USB
> device number 2 using xhci_hcd' | wc -l
> 75
>
> This is what I have:
>
> root# lsusb -s 004:001
> Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
>
> root# lsusb -s 004:002
> Bus 004 Device 002: ID 174c:55aa ASMedia Technology Inc. ASM1051E SATA
> 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge,
> ASM1153E SATA 6Gb/s bridge
>
> My external USB 3.0 HDD contains the partition with my Debian-system
> and is attached to the above xhci bus/device.
>
> Can you enlighten what this means?
> Is this a known issue?
> Is there a fix around?
>
> BTW, in which Git tree is the xhci development happening?
> Can you point me to it?
>
> I am attaching my linux-config and full dmesg-log.
>
> Also I have attached outputs of:
>
> $ sudo lsusb -vvv -d 1d6b:0003
> $ sudo lsusb -vvv -d 174c:55aa
>
> If you need further information, please let me know.
>
> Thanks.
>

Looks like that xhci-reset happens here every 10min.

- Sedat -


2021-03-01 09:06:26

by Sedat Dilek

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

On Wed, Feb 24, 2021 at 6:25 PM Sedat Dilek <[email protected]> wrote:
>
> On Wed, Feb 24, 2021 at 2:44 PM Sedat Dilek <[email protected]> wrote:
> >
> > Hi Mathias,
> >
> > I am here on Linux-v5.11-10201-gc03c21ba6f4e.
> >
> > I see a lot xhci-resets in my dmesg-log:
> >
> > root# LC_ALL=C dmesg -T | grep 'usb 4-1: reset SuperSpeed Gen 1 USB
> > device number 2 using xhci_hcd' | wc -l
> > 75
> >
> > This is what I have:
> >
> > root# lsusb -s 004:001
> > Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
> >
> > root# lsusb -s 004:002
> > Bus 004 Device 002: ID 174c:55aa ASMedia Technology Inc. ASM1051E SATA
> > 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge,
> > ASM1153E SATA 6Gb/s bridge
> >
> > My external USB 3.0 HDD contains the partition with my Debian-system
> > and is attached to the above xhci bus/device.
> >
> > Can you enlighten what this means?
> > Is this a known issue?
> > Is there a fix around?
> >
> > BTW, in which Git tree is the xhci development happening?
> > Can you point me to it?
> >
> > I am attaching my linux-config and full dmesg-log.
> >
> > Also I have attached outputs of:
> >
> > $ sudo lsusb -vvv -d 1d6b:0003
> > $ sudo lsusb -vvv -d 174c:55aa
> >
> > If you need further information, please let me know.
> >
> > Thanks.
> >
>
> Looks like that xhci-reset happens here every 10min.
>

[ To Greg ]

The problem still remains with Linux v5.12-rc1 (see [1]).

Yesterday, I ran some disk-health checks with smartctl and gsmartcontrol.
All good.

For the first time I used badblocks from e2fsprogs Debian package:

root# LC_ALL=C badblocks -v -p 1 -s /dev/sdc -o
badblocks-v-p-1-s_dev-sdc_$(uname -r).txt
Checking blocks 0 to 976762583
Checking for bad blocks (read-only test): done
Pass completed, 0 bad blocks found. (0/0/0 errors)

Good, there is no file-system corruption or badblocks or even a hardware damage.

Anyway, feedback is much appreciated.

Thanks.

Regards,
- Sedat -

[1] https://lore.kernel.org/lkml/CA+icZUUjVnBjC4AJTT9LYS4J+QbuQZUVj5XdW+iPmjxxuODVmA@mail.gmail.com/

2021-03-03 04:44:39

by Alan Stern

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

On Mon, Mar 01, 2021 at 09:54:38AM +0100, Sedat Dilek wrote:
> On Wed, Feb 24, 2021 at 6:25 PM Sedat Dilek <[email protected]> wrote:
> >
> > On Wed, Feb 24, 2021 at 2:44 PM Sedat Dilek <[email protected]> wrote:
> > >
> > > Hi Mathias,
> > >
> > > I am here on Linux-v5.11-10201-gc03c21ba6f4e.
> > >
> > > I see a lot xhci-resets in my dmesg-log:
> > >
> > > root# LC_ALL=C dmesg -T | grep 'usb 4-1: reset SuperSpeed Gen 1 USB
> > > device number 2 using xhci_hcd' | wc -l
> > > 75
> > >
> > > This is what I have:
> > >
> > > root# lsusb -s 004:001
> > > Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
> > >
> > > root# lsusb -s 004:002
> > > Bus 004 Device 002: ID 174c:55aa ASMedia Technology Inc. ASM1051E SATA
> > > 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge,
> > > ASM1153E SATA 6Gb/s bridge
> > >
> > > My external USB 3.0 HDD contains the partition with my Debian-system
> > > and is attached to the above xhci bus/device.
> > >
> > > Can you enlighten what this means?
> > > Is this a known issue?
> > > Is there a fix around?
> > >
> > > BTW, in which Git tree is the xhci development happening?
> > > Can you point me to it?
> > >
> > > I am attaching my linux-config and full dmesg-log.
> > >
> > > Also I have attached outputs of:
> > >
> > > $ sudo lsusb -vvv -d 1d6b:0003
> > > $ sudo lsusb -vvv -d 174c:55aa
> > >
> > > If you need further information, please let me know.
> > >
> > > Thanks.
> > >
> >
> > Looks like that xhci-reset happens here every 10min.
> >
>
> [ To Greg ]
>
> The problem still remains with Linux v5.12-rc1 (see [1]).
>
> Yesterday, I ran some disk-health checks with smartctl and gsmartcontrol.
> All good.
>
> For the first time I used badblocks from e2fsprogs Debian package:
>
> root# LC_ALL=C badblocks -v -p 1 -s /dev/sdc -o
> badblocks-v-p-1-s_dev-sdc_$(uname -r).txt
> Checking blocks 0 to 976762583
> Checking for bad blocks (read-only test): done
> Pass completed, 0 bad blocks found. (0/0/0 errors)
>
> Good, there is no file-system corruption or badblocks or even a hardware damage.
>
> Anyway, feedback is much appreciated.
>
> Thanks.

You can use usbmon on bus 4 to record the USB traffic. It may indicate
why the resets occur.

Alan Stern

2021-03-05 12:12:00

by Sedat Dilek

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

On Mon, Mar 1, 2021 at 4:53 PM Alan Stern <[email protected]> wrote:
[ ... ]
> You can use usbmon on bus 4 to record the USB traffic. It may indicate
> why the resets occur.
>

Hi Alan,

I followed the instructions in [1].

root# modprobe -v usbmon

root# ls /sys/kernel/debug/usb/usbmon
0s 0u 1s 1t 1u 2s 2t 2u 3s 3t 3u 4s 4t 4u

root# cat /sys/kernel/debug/usb/usbmon/4u > /tmp/usbmon-log_4u.txt
[ Ctrl+C ]

I recorded 13:03 - 13:04 (one minute).

So these xhci-resets should be included:

[Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd

The usbmon-log is attached.

Unsure how to interpret the log - the kernel-doc says `raw data`.
How can I bring this into a human-readable format?
Can you give me a hand?

Regards,
- Sedat -

[1] https://www.kernel.org/doc/Documentation/usb/usbmon.


Attachments:
usbmon-log_4u.txt (161.94 kB)

2021-03-05 16:09:18

by Alan Stern

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

On Fri, Mar 05, 2021 at 01:09:16PM +0100, Sedat Dilek wrote:
> On Mon, Mar 1, 2021 at 4:53 PM Alan Stern <[email protected]> wrote:
> [ ... ]
> > You can use usbmon on bus 4 to record the USB traffic. It may indicate
> > why the resets occur.
> >
>
> Hi Alan,
>
> I followed the instructions in [1].
>
> root# modprobe -v usbmon
>
> root# ls /sys/kernel/debug/usb/usbmon
> 0s 0u 1s 1t 1u 2s 2t 2u 3s 3t 3u 4s 4t 4u
>
> root# cat /sys/kernel/debug/usb/usbmon/4u > /tmp/usbmon-log_4u.txt
> [ Ctrl+C ]
>
> I recorded 13:03 - 13:04 (one minute).
>
> So these xhci-resets should be included:
>
> [Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
>
> The usbmon-log is attached.
>
> Unsure how to interpret the log - the kernel-doc says `raw data`.
> How can I bring this into a human-readable format?
> Can you give me a hand?

Don't worry about trying to decode the output. To me it looks like the
drive crashes and needs to be reset at times when the computer sends it
an ATA command. (Not all ATA commands, but some.) You can prevent this
by setting the following module parameter for the usb-storage driver:

quirks=174c:55aa:t

where the two numbers are the Vendor and Product IDs for the external
drive, and the 't' is a quirks flag saying not to use any ATA commands.
If this module parameter fixes the problem, we can add a permanent quirk
setting to the kernel.

Alan Stern

2021-03-05 19:08:29

by Sedat Dilek

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

On Fri, Mar 5, 2021 at 5:07 PM Alan Stern <[email protected]> wrote:
>
> On Fri, Mar 05, 2021 at 01:09:16PM +0100, Sedat Dilek wrote:
> > On Mon, Mar 1, 2021 at 4:53 PM Alan Stern <[email protected]> wrote:
> > [ ... ]
> > > You can use usbmon on bus 4 to record the USB traffic. It may indicate
> > > why the resets occur.
> > >
> >
> > Hi Alan,
> >
> > I followed the instructions in [1].
> >
> > root# modprobe -v usbmon
> >
> > root# ls /sys/kernel/debug/usb/usbmon
> > 0s 0u 1s 1t 1u 2s 2t 2u 3s 3t 3u 4s 4t 4u
> >
> > root# cat /sys/kernel/debug/usb/usbmon/4u > /tmp/usbmon-log_4u.txt
> > [ Ctrl+C ]
> >
> > I recorded 13:03 - 13:04 (one minute).
> >
> > So these xhci-resets should be included:
> >
> > [Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> >
> > The usbmon-log is attached.
> >
> > Unsure how to interpret the log - the kernel-doc says `raw data`.
> > How can I bring this into a human-readable format?
> > Can you give me a hand?
>
> Don't worry about trying to decode the output. To me it looks like the
> drive crashes and needs to be reset at times when the computer sends it
> an ATA command. (Not all ATA commands, but some.) You can prevent this
> by setting the following module parameter for the usb-storage driver:
>
> quirks=174c:55aa:t
>
> where the two numbers are the Vendor and Product IDs for the external
> drive, and the 't' is a quirks flag saying not to use any ATA commands.
> If this module parameter fixes the problem, we can add a permanent quirk
> setting to the kernel.
>

Thanks Alan.

I did:

[ /etc/modules-load.d/usb-storage.conf ]

# Add quirks for ATA commands for usb-storage devices connected to
ASMedia M1042 USB-3.0 controller
options usb-storage quirks=174c:55aa:t
- EOF -

It is:

/lib/modules/5.12.0-rc1-11-amd64-clang13-cfi/kernel/drivers/usb/storage/usb-storage.ko

But:

root# lsmod | grep usb | grep storage
usb_storage 90112 2 uas
scsi_mod 307200 6 sd_mod,usb_storage,uas,libata,sg,sr_mod
usbcore 385024 14
usbserial,xhci_hcd,ehci_pci,usbnet,usbhid,usb_storage,usb_wwan,uvcvideo,ehci_hcd,btusb,xhci_pci,cdc_ether,uas,option

I have not rebooted yet.

Interferences with PowerTop?

These xhci-resets happen every 10mins in a sequence of 4.

I have here a powertop.service (systemd) with passing --auto-tune option.
That was not a problem with previous Linux-kernels >= v5.12-rc1, so.

Alan, what do you think?

- Sedat -

2021-03-05 19:24:59

by Sedat Dilek

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

On Fri, Mar 5, 2021 at 8:05 PM Sedat Dilek <[email protected]> wrote:
>
> On Fri, Mar 5, 2021 at 5:07 PM Alan Stern <[email protected]> wrote:
> >
> > On Fri, Mar 05, 2021 at 01:09:16PM +0100, Sedat Dilek wrote:
> > > On Mon, Mar 1, 2021 at 4:53 PM Alan Stern <[email protected]> wrote:
> > > [ ... ]
> > > > You can use usbmon on bus 4 to record the USB traffic. It may indicate
> > > > why the resets occur.
> > > >
> > >
> > > Hi Alan,
> > >
> > > I followed the instructions in [1].
> > >
> > > root# modprobe -v usbmon
> > >
> > > root# ls /sys/kernel/debug/usb/usbmon
> > > 0s 0u 1s 1t 1u 2s 2t 2u 3s 3t 3u 4s 4t 4u
> > >
> > > root# cat /sys/kernel/debug/usb/usbmon/4u > /tmp/usbmon-log_4u.txt
> > > [ Ctrl+C ]
> > >
> > > I recorded 13:03 - 13:04 (one minute).
> > >
> > > So these xhci-resets should be included:
> > >
> > > [Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > > [Fri Mar 5 13:03:07 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > > [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > > [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > > [Fri Mar 5 13:03:27 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > > [Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > > [Fri Mar 5 13:03:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > > number 2 using xhci_hcd
> > >
> > > The usbmon-log is attached.
> > >
> > > Unsure how to interpret the log - the kernel-doc says `raw data`.
> > > How can I bring this into a human-readable format?
> > > Can you give me a hand?
> >
> > Don't worry about trying to decode the output. To me it looks like the
> > drive crashes and needs to be reset at times when the computer sends it
> > an ATA command. (Not all ATA commands, but some.) You can prevent this
> > by setting the following module parameter for the usb-storage driver:
> >
> > quirks=174c:55aa:t
> >
> > where the two numbers are the Vendor and Product IDs for the external
> > drive, and the 't' is a quirks flag saying not to use any ATA commands.
> > If this module parameter fixes the problem, we can add a permanent quirk
> > setting to the kernel.
> >
>
> Thanks Alan.
>
> I did:
>
> [ /etc/modules-load.d/usb-storage.conf ]
>
> # Add quirks for ATA commands for usb-storage devices connected to
> ASMedia M1042 USB-3.0 controller
> options usb-storage quirks=174c:55aa:t
> - EOF -
>
> It is:
>
> /lib/modules/5.12.0-rc1-11-amd64-clang13-cfi/kernel/drivers/usb/storage/usb-storage.ko
>
> But:
>
> root# lsmod | grep usb | grep storage
> usb_storage 90112 2 uas
> scsi_mod 307200 6 sd_mod,usb_storage,uas,libata,sg,sr_mod
> usbcore 385024 14
> usbserial,xhci_hcd,ehci_pci,usbnet,usbhid,usb_storage,usb_wwan,uvcvideo,ehci_hcd,btusb,xhci_pci,cdc_ether,uas,option
>
> I have not rebooted yet.
>
> Interferences with PowerTop?
>
> These xhci-resets happen every 10mins in a sequence of 4.
>
> I have here a powertop.service (systemd) with passing --auto-tune option.
> That was not a problem with previous Linux-kernels >= v5.12-rc1, so.
>
> Alan, what do you think?
>

The quirks match:

[Fri Mar 5 20:06:56 2021] usb-storage 4-1:1.0: USB Mass Storage device detected
[Fri Mar 5 20:06:56 2021] usb-storage 4-1:1.0: Quirks match for vid
174c pid 55aa: 400000

That seems not to be the trick:

root# LC_ALL=C dmesg -T | grep 'usb 4-1:'
[Fri Mar 5 20:06:55 2021] usb 4-1: new SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:55 2021] usb 4-1: New USB device found,
idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[Fri Mar 5 20:06:55 2021] usb 4-1: New USB device strings: Mfr=2,
Product=3, SerialNumber=1
[Fri Mar 5 20:06:55 2021] usb 4-1: Product: MEDION HDDrive-n-GO
[Fri Mar 5 20:06:55 2021] usb 4-1: Manufacturer: MEDION
[Fri Mar 5 20:06:55 2021] usb 4-1: SerialNumber: 3180000000000000092C
[Fri Mar 5 20:06:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:58 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:58 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:58 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:58 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:58 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:59 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:59 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:59 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:06:59 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:00 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:00 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:00 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:00 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:00 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:01 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:01 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:01 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:01 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:02 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:02 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:02 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:02 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:28 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:30 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:37 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:38 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:39 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:39 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:39 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:46 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:47 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:48 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:49 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:52 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:52 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:52 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:52 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:53 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:53 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:54 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:54 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:55 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:55 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:55 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:55 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:56 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:56 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:07:56 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:09:09 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:17:56 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:17:56 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:17:56 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:17:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd
[Fri Mar 5 20:17:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
number 2 using xhci_hcd

- Sedat -

2021-03-05 19:28:09

by Alan Stern

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

On Fri, Mar 05, 2021 at 08:05:49PM +0100, Sedat Dilek wrote:
> On Fri, Mar 5, 2021 at 5:07 PM Alan Stern <[email protected]> wrote:

> > Don't worry about trying to decode the output. To me it looks like the
> > drive crashes and needs to be reset at times when the computer sends it
> > an ATA command. (Not all ATA commands, but some.) You can prevent this
> > by setting the following module parameter for the usb-storage driver:
> >
> > quirks=174c:55aa:t
> >
> > where the two numbers are the Vendor and Product IDs for the external
> > drive, and the 't' is a quirks flag saying not to use any ATA commands.
> > If this module parameter fixes the problem, we can add a permanent quirk
> > setting to the kernel.
> >
>
> Thanks Alan.
>
> I did:
>
> [ /etc/modules-load.d/usb-storage.conf ]
>
> # Add quirks for ATA commands for usb-storage devices connected to
> ASMedia M1042 USB-3.0 controller
> options usb-storage quirks=174c:55aa:t
> - EOF -
>
> It is:
>
> /lib/modules/5.12.0-rc1-11-amd64-clang13-cfi/kernel/drivers/usb/storage/usb-storage.ko
>
> But:
>
> root# lsmod | grep usb | grep storage
> usb_storage 90112 2 uas
> scsi_mod 307200 6 sd_mod,usb_storage,uas,libata,sg,sr_mod
> usbcore 385024 14
> usbserial,xhci_hcd,ehci_pci,usbnet,usbhid,usb_storage,usb_wwan,uvcvideo,ehci_hcd,btusb,xhci_pci,cdc_ether,uas,option

I don't understand. What is the point of this listing?

> I have not rebooted yet.

Depending on how your system is set up, the new usb-storage.conf file
might need to be copied into the initramfs image.

However, you don't need to reload the driver module or reboot. To make
the new quirk take effect, all you have to do is write 174c:55aa:t to
/sys/module/usb_storage/parameters/quirks.

> Interferences with PowerTop?

Maybe. It's entirely possible that PowerTop or some other program is
issuing the troublesome ATA commands.

> These xhci-resets happen every 10mins in a sequence of 4.
>
> I have here a powertop.service (systemd) with passing --auto-tune option.
> That was not a problem with previous Linux-kernels >= v5.12-rc1, so.
>
> Alan, what do you think?

Try turning the service off and see if that makes any difference.

Alan Stern

2021-03-05 19:32:10

by Alan Stern

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

On Fri, Mar 05, 2021 at 08:22:22PM +0100, Sedat Dilek wrote:
> The quirks match:
>
> [Fri Mar 5 20:06:56 2021] usb-storage 4-1:1.0: USB Mass Storage device detected
> [Fri Mar 5 20:06:56 2021] usb-storage 4-1:1.0: Quirks match for vid
> 174c pid 55aa: 400000
>
> That seems not to be the trick:
>
> root# LC_ALL=C dmesg -T | grep 'usb 4-1:'
> [Fri Mar 5 20:06:55 2021] usb 4-1: new SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd
> [Fri Mar 5 20:06:55 2021] usb 4-1: New USB device found,
> idVendor=174c, idProduct=55aa, bcdDevice= 1.00
> [Fri Mar 5 20:06:55 2021] usb 4-1: New USB device strings: Mfr=2,
> Product=3, SerialNumber=1
> [Fri Mar 5 20:06:55 2021] usb 4-1: Product: MEDION HDDrive-n-GO
> [Fri Mar 5 20:06:55 2021] usb 4-1: Manufacturer: MEDION
> [Fri Mar 5 20:06:55 2021] usb 4-1: SerialNumber: 3180000000000000092C
> [Fri Mar 5 20:06:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> number 2 using xhci_hcd

Okay, that indicates the ATA commands are being sent not by the kernel
but by some program. I'm not sure how you can easily find out which
program; probably the best thing to do is turn them off one by one until
you find the one responsible.

Alan Stern

2021-03-05 19:39:25

by Sedat Dilek

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

On Fri, Mar 5, 2021 at 8:25 PM Alan Stern <[email protected]> wrote:
>
> On Fri, Mar 05, 2021 at 08:05:49PM +0100, Sedat Dilek wrote:
> > On Fri, Mar 5, 2021 at 5:07 PM Alan Stern <[email protected]> wrote:
>
> > > Don't worry about trying to decode the output. To me it looks like the
> > > drive crashes and needs to be reset at times when the computer sends it
> > > an ATA command. (Not all ATA commands, but some.) You can prevent this
> > > by setting the following module parameter for the usb-storage driver:
> > >
> > > quirks=174c:55aa:t
> > >
> > > where the two numbers are the Vendor and Product IDs for the external
> > > drive, and the 't' is a quirks flag saying not to use any ATA commands.
> > > If this module parameter fixes the problem, we can add a permanent quirk
> > > setting to the kernel.
> > >
> >
> > Thanks Alan.
> >
> > I did:
> >
> > [ /etc/modules-load.d/usb-storage.conf ]
> >
> > # Add quirks for ATA commands for usb-storage devices connected to
> > ASMedia M1042 USB-3.0 controller
> > options usb-storage quirks=174c:55aa:t
> > - EOF -
> >
> > It is:
> >
> > /lib/modules/5.12.0-rc1-11-amd64-clang13-cfi/kernel/drivers/usb/storage/usb-storage.ko
> >
> > But:
> >
> > root# lsmod | grep usb | grep storage
> > usb_storage 90112 2 uas
> > scsi_mod 307200 6 sd_mod,usb_storage,uas,libata,sg,sr_mod
> > usbcore 385024 14
> > usbserial,xhci_hcd,ehci_pci,usbnet,usbhid,usb_storage,usb_wwan,uvcvideo,ehci_hcd,btusb,xhci_pci,cdc_ether,uas,option
>
> I don't understand. What is the point of this listing?
>

I was confused about lsmod and modinfo output:
usb-storage.ko (kernel-module name) VS. usb_storage (modinfo: name: usb_storage)

> > I have not rebooted yet.
>
> Depending on how your system is set up, the new usb-storage.conf file
> might need to be copied into the initramfs image.
>

That seems not to be needed.

> However, you don't need to reload the driver module or reboot. To make
> the new quirk take effect, all you have to do is write 174c:55aa:t to
> /sys/module/usb_storage/parameters/quirks.
>

OK, keep this for next USB(mon) testings before doing a reboot.

> > Interferences with PowerTop?
>
> Maybe. It's entirely possible that PowerTop or some other program is
> issuing the troublesome ATA commands.
>
> > These xhci-resets happen every 10mins in a sequence of 4.
> >
> > I have here a powertop.service (systemd) with passing --auto-tune option.
> > That was not a problem with previous Linux-kernels >= v5.12-rc1, so.
> >
> > Alan, what do you think?
>
> Try turning the service off and see if that makes any difference.
>

NO, it is not powertop.service causing the xhci-resets.

- Sedat -

2021-03-05 19:46:12

by Sedat Dilek

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

On Fri, Mar 5, 2021 at 8:30 PM Alan Stern <[email protected]> wrote:
>
> On Fri, Mar 05, 2021 at 08:22:22PM +0100, Sedat Dilek wrote:
> > The quirks match:
> >
> > [Fri Mar 5 20:06:56 2021] usb-storage 4-1:1.0: USB Mass Storage device detected
> > [Fri Mar 5 20:06:56 2021] usb-storage 4-1:1.0: Quirks match for vid
> > 174c pid 55aa: 400000
> >
> > That seems not to be the trick:
> >
> > root# LC_ALL=C dmesg -T | grep 'usb 4-1:'
> > [Fri Mar 5 20:06:55 2021] usb 4-1: new SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
> > [Fri Mar 5 20:06:55 2021] usb 4-1: New USB device found,
> > idVendor=174c, idProduct=55aa, bcdDevice= 1.00
> > [Fri Mar 5 20:06:55 2021] usb 4-1: New USB device strings: Mfr=2,
> > Product=3, SerialNumber=1
> > [Fri Mar 5 20:06:55 2021] usb 4-1: Product: MEDION HDDrive-n-GO
> > [Fri Mar 5 20:06:55 2021] usb 4-1: Manufacturer: MEDION
> > [Fri Mar 5 20:06:55 2021] usb 4-1: SerialNumber: 3180000000000000092C
> > [Fri Mar 5 20:06:57 2021] usb 4-1: reset SuperSpeed Gen 1 USB device
> > number 2 using xhci_hcd
>
> Okay, that indicates the ATA commands are being sent not by the kernel
> but by some program. I'm not sure how you can easily find out which
> program; probably the best thing to do is turn them off one by one until
> you find the one responsible.
>

I can hardly imagine which user-space tools other than powertop can
interfere here.
Any ideas?

I will remove or better comment the quirks in
/etc/modules-load.d/usb-storage.conf for now.

- Sedat -

2021-03-05 19:49:37

by Alan Stern

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

On Fri, Mar 05, 2021 at 08:41:40PM +0100, Sedat Dilek wrote:
> On Fri, Mar 5, 2021 at 8:30 PM Alan Stern <[email protected]> wrote:

> > Okay, that indicates the ATA commands are being sent not by the kernel
> > but by some program. I'm not sure how you can easily find out which
> > program; probably the best thing to do is turn them off one by one until
> > you find the one responsible.
> >
>
> I can hardly imagine which user-space tools other than powertop can
> interfere here.
> Any ideas?

No. Especially since I have no idea what programs are running on your
computer.

Alan Stern

2021-03-05 19:57:05

by Sedat Dilek

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

On Fri, Mar 5, 2021 at 8:47 PM Alan Stern <[email protected]> wrote:
>
> On Fri, Mar 05, 2021 at 08:41:40PM +0100, Sedat Dilek wrote:
> > On Fri, Mar 5, 2021 at 8:30 PM Alan Stern <[email protected]> wrote:
>
> > > Okay, that indicates the ATA commands are being sent not by the kernel
> > > but by some program. I'm not sure how you can easily find out which
> > > program; probably the best thing to do is turn them off one by one until
> > > you find the one responsible.
> > >
> >
> > I can hardly imagine which user-space tools other than powertop can
> > interfere here.
> > Any ideas?
>
> No. Especially since I have no idea what programs are running on your
> computer.
>

Are we talking about things like gvfs - udisks - fuse etc.?
All running via systemd here.

Here I am using KDE/Plasma as DE.
Unsure if this runs apps in the background.

AFAICS I have not seen xhci-resets with Debian-Kernel 5.10.19-1.

- Sedat -

2021-03-06 06:54:42

by Sedat Dilek

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

On Fri, Mar 5, 2021 at 8:54 PM Sedat Dilek <[email protected]> wrote:
>
> On Fri, Mar 5, 2021 at 8:47 PM Alan Stern <[email protected]> wrote:
> >
> > On Fri, Mar 05, 2021 at 08:41:40PM +0100, Sedat Dilek wrote:
> > > On Fri, Mar 5, 2021 at 8:30 PM Alan Stern <[email protected]> wrote:
> >
> > > > Okay, that indicates the ATA commands are being sent not by the kernel
> > > > but by some program. I'm not sure how you can easily find out which
> > > > program; probably the best thing to do is turn them off one by one until
> > > > you find the one responsible.
> > > >
> > >
> > > I can hardly imagine which user-space tools other than powertop can
> > > interfere here.
> > > Any ideas?
> >
> > No. Especially since I have no idea what programs are running on your
> > computer.
> >
>
> Are we talking about things like gvfs - udisks - fuse etc.?
> All running via systemd here.
>
> Here I am using KDE/Plasma as DE.
> Unsure if this runs apps in the background.
>
> AFAICS I have not seen xhci-resets with Debian-Kernel 5.10.19-1.
>

No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:

root# cat /proc/version
Linux version 5.10.0-4-amd64 ([email protected]) (gcc-10
(Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian)
2.35.2) #1 SMP Debian 5.10.19-1 (2021-03-02)

root# LC_ALL=C dmesg -T | grep xhci | grep reset
[ empty ]

But I see there is already a quirk enabled and matches my ASmedia USB
3.0 controller (as I have *no* usb-storage-quirks enabled):

root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
[Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
174c pid 55aa: 400000

For the sake of completeness my latest /etc/modules-load.d/usb-storage.conf:

# Add quirks for USB Mass Storage devices
#
# Link: https://www.kernel.org/doc/html/latest/admin-guide/kernel-parameters.html
#
# usb-storage quirks kernel-parameters and options explained:
# [1] Usage: usb-storage.quirks=<VID:PID:Flags>
# [2] VendorID (VID) and ProductID (PID):
# ASMedia M1042 USB-3.0 controller: VID: 174c PID: 55aa
# [3] Flags:
# t = NO_ATA_1X (don't allow ATA(12) and ATA(16) commands, uas only);
# u = IGNORE_UAS (don't bind to the uas driver);
# [4] Example: usb-storage.quirks=174c:55aa:t
#
# DEBUG: echo '174c:55aa:t' > /sys/module/usb_storage/parameters/quirks
#
# XXX: Commented - xhci-resets NOT caused by the Linux-kernel (check user-space)
#options usb-storage quirks=174c:55aa:t
- EOF -

Thanks Alan for all the hints and tips in the topic "usb-storage and
quirks" and your patience.

- Sedat -

2021-03-06 17:00:05

by Alan Stern

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

On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:

Is the kernel the only thing that is different? The rest of the
operating system and environment is exactly the same?

> But I see there is already a quirk enabled and matches my ASmedia USB
> 3.0 controller (as I have *no* usb-storage-quirks enabled):
>
> root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> 174c pid 55aa: 400000

Yes, this is because that type of device already has a quirk entry built
into the kernel. You can find it by searching for "174c" in the kernel
source file drivers/usb/storage/unusual_devs.h.

> Thanks Alan for all the hints and tips in the topic "usb-storage and
> quirks" and your patience.

You can try building a 5.11 kernel with the patch below. I don't know
whether it will show anything in the dmesg log when one of these resets
occurs, but it might.

If that doesn't work out, another possibility is to use git bisect to
find the commit between 5.10 and 5.11 which caused the problem to start.

Alan Stern


--- usb-devel.orig/block/scsi_ioctl.c
+++ usb-devel/block/scsi_ioctl.c
@@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
hdr->host_status = host_byte(req->result);
hdr->driver_status = driver_byte(req->result);
hdr->info = 0;
- if (hdr->masked_status || hdr->host_status || hdr->driver_status)
+ if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
hdr->info |= SG_INFO_CHECK;
+ printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
+ req->cmd[0], current->comm);
+ }
hdr->resid = req->resid_len;
hdr->sb_len_wr = 0;


2021-03-06 19:36:56

by Sedat Dilek

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

On Sat, Mar 6, 2021 at 5:58 PM Alan Stern <[email protected]> wrote:
>
> On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> > No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:
>
> Is the kernel the only thing that is different? The rest of the
> operating system and environment is exactly the same?
>

The kernel is the only change.

> > But I see there is already a quirk enabled and matches my ASmedia USB
> > 3.0 controller (as I have *no* usb-storage-quirks enabled):
> >
> > root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> > [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> > 174c pid 55aa: 400000
>
> Yes, this is because that type of device already has a quirk entry built
> into the kernel. You can find it by searching for "174c" in the kernel
> source file drivers/usb/storage/unusual_devs.h.
>

OK, will look into it.

> > Thanks Alan for all the hints and tips in the topic "usb-storage and
> > quirks" and your patience.
>
> You can try building a 5.11 kernel with the patch below. I don't know
> whether it will show anything in the dmesg log when one of these resets
> occurs, but it might.
>
> If that doesn't work out, another possibility is to use git bisect to
> find the commit between 5.10 and 5.11 which caused the problem to start.
>

This is with Linux v5.12-rc2 - not v5.11.y.
I look if I can apply the patch.

- Sedat -

>
>
> --- usb-devel.orig/block/scsi_ioctl.c
> +++ usb-devel/block/scsi_ioctl.c
> @@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
> hdr->host_status = host_byte(req->result);
> hdr->driver_status = driver_byte(req->result);
> hdr->info = 0;
> - if (hdr->masked_status || hdr->host_status || hdr->driver_status)
> + if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
> hdr->info |= SG_INFO_CHECK;
> + printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
> + req->cmd[0], current->comm);
> + }
> hdr->resid = req->resid_len;
> hdr->sb_len_wr = 0;
>
>

2021-03-06 20:28:34

by Sedat Dilek

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

On Sat, Mar 6, 2021 at 5:58 PM Alan Stern <[email protected]> wrote:
>
> On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> > No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:
>
> Is the kernel the only thing that is different? The rest of the
> operating system and environment is exactly the same?
>
> > But I see there is already a quirk enabled and matches my ASmedia USB
> > 3.0 controller (as I have *no* usb-storage-quirks enabled):
> >
> > root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> > [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> > 174c pid 55aa: 400000
>
> Yes, this is because that type of device already has a quirk entry built
> into the kernel. You can find it by searching for "174c" in the kernel
> source file drivers/usb/storage/unusual_devs.h.
>
> > Thanks Alan for all the hints and tips in the topic "usb-storage and
> > quirks" and your patience.
>
> You can try building a 5.11 kernel with the patch below. I don't know
> whether it will show anything in the dmesg log when one of these resets
> occurs, but it might.
>
> If that doesn't work out, another possibility is to use git bisect to
> find the commit between 5.10 and 5.11 which caused the problem to start.
>
> Alan Stern
>
>
> --- usb-devel.orig/block/scsi_ioctl.c
> +++ usb-devel/block/scsi_ioctl.c
> @@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
> hdr->host_status = host_byte(req->result);
> hdr->driver_status = driver_byte(req->result);
> hdr->info = 0;
> - if (hdr->masked_status || hdr->host_status || hdr->driver_status)
> + if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
> hdr->info |= SG_INFO_CHECK;
> + printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
> + req->cmd[0], current->comm);
> + }
> hdr->resid = req->resid_len;
> hdr->sb_len_wr = 0;
>
>

Thanks for the diff, Alan.

With an adapted version to fit Linux v5.12-rc2 (see attachment) I see:

root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error'
[Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:16:45 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:15 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:16 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
[Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd A1, prog ata_id
[Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:34 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
[Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
[Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
[Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
[Sat Mar 6 21:18:55 2021] SCSI ioctl error, cmd 85, prog smartctl
[Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
[Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl

My linux-config and full dmesg-log are attached.

- Sedat -


Attachments:
dmesg-T_5.12.0-rc2-2-amd64-clang13-cfi.txt (81.51 kB)
1-xhci-resets-alanstern-dileks-v2.diff (669.00 B)
config-5.12.0-rc2-2-amd64-clang13-cfi (233.80 kB)
Download all attachments

2021-03-06 20:42:30

by Sedat Dilek

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

On Sat, Mar 6, 2021 at 9:26 PM Sedat Dilek <[email protected]> wrote:
>
> On Sat, Mar 6, 2021 at 5:58 PM Alan Stern <[email protected]> wrote:
> >
> > On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> > > No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:
> >
> > Is the kernel the only thing that is different? The rest of the
> > operating system and environment is exactly the same?
> >
> > > But I see there is already a quirk enabled and matches my ASmedia USB
> > > 3.0 controller (as I have *no* usb-storage-quirks enabled):
> > >
> > > root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> > > [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> > > 174c pid 55aa: 400000
> >
> > Yes, this is because that type of device already has a quirk entry built
> > into the kernel. You can find it by searching for "174c" in the kernel
> > source file drivers/usb/storage/unusual_devs.h.
> >
> > > Thanks Alan for all the hints and tips in the topic "usb-storage and
> > > quirks" and your patience.
> >
> > You can try building a 5.11 kernel with the patch below. I don't know
> > whether it will show anything in the dmesg log when one of these resets
> > occurs, but it might.
> >
> > If that doesn't work out, another possibility is to use git bisect to
> > find the commit between 5.10 and 5.11 which caused the problem to start.
> >
> > Alan Stern
> >
> >
> > --- usb-devel.orig/block/scsi_ioctl.c
> > +++ usb-devel/block/scsi_ioctl.c
> > @@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
> > hdr->host_status = host_byte(req->result);
> > hdr->driver_status = driver_byte(req->result);
> > hdr->info = 0;
> > - if (hdr->masked_status || hdr->host_status || hdr->driver_status)
> > + if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
> > hdr->info |= SG_INFO_CHECK;
> > + printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
> > + req->cmd[0], current->comm);
> > + }
> > hdr->resid = req->resid_len;
> > hdr->sb_len_wr = 0;
> >
> >
>
> Thanks for the diff, Alan.
>
> With an adapted version to fit Linux v5.12-rc2 (see attachment) I see:
>
> root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error'
> [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:16:45 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:15 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:16 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd A1, prog ata_id
> [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:34 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> [Sat Mar 6 21:18:55 2021] SCSI ioctl error, cmd 85, prog smartctl
> [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
>
> My linux-config and full dmesg-log are attached.
>

Checking dmesg again...

So, this is pool-udisksd (cmd A1 and 85) and smartctl (cmd 85) causing
regular xhci-resets.

SCSI ioctl error, cmd 85, prog smartctl

SCSI ioctl error, cmd A1, prog pool-udisksd
SCSI ioctl error, cmd 85, prog pool-udisksd

- Sedat -

2021-03-06 20:56:14

by Sedat Dilek

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

On Sat, Mar 6, 2021 at 9:38 PM Sedat Dilek <[email protected]> wrote:
>
> On Sat, Mar 6, 2021 at 9:26 PM Sedat Dilek <[email protected]> wrote:
> >
> > On Sat, Mar 6, 2021 at 5:58 PM Alan Stern <[email protected]> wrote:
> > >
> > > On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> > > > No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:
> > >
> > > Is the kernel the only thing that is different? The rest of the
> > > operating system and environment is exactly the same?
> > >
> > > > But I see there is already a quirk enabled and matches my ASmedia USB
> > > > 3.0 controller (as I have *no* usb-storage-quirks enabled):
> > > >
> > > > root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> > > > [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> > > > 174c pid 55aa: 400000
> > >
> > > Yes, this is because that type of device already has a quirk entry built
> > > into the kernel. You can find it by searching for "174c" in the kernel
> > > source file drivers/usb/storage/unusual_devs.h.
> > >
> > > > Thanks Alan for all the hints and tips in the topic "usb-storage and
> > > > quirks" and your patience.
> > >
> > > You can try building a 5.11 kernel with the patch below. I don't know
> > > whether it will show anything in the dmesg log when one of these resets
> > > occurs, but it might.
> > >
> > > If that doesn't work out, another possibility is to use git bisect to
> > > find the commit between 5.10 and 5.11 which caused the problem to start.
> > >
> > > Alan Stern
> > >
> > >
> > > --- usb-devel.orig/block/scsi_ioctl.c
> > > +++ usb-devel/block/scsi_ioctl.c
> > > @@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
> > > hdr->host_status = host_byte(req->result);
> > > hdr->driver_status = driver_byte(req->result);
> > > hdr->info = 0;
> > > - if (hdr->masked_status || hdr->host_status || hdr->driver_status)
> > > + if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
> > > hdr->info |= SG_INFO_CHECK;
> > > + printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
> > > + req->cmd[0], current->comm);
> > > + }
> > > hdr->resid = req->resid_len;
> > > hdr->sb_len_wr = 0;
> > >
> > >
> >
> > Thanks for the diff, Alan.
> >
> > With an adapted version to fit Linux v5.12-rc2 (see attachment) I see:
> >
> > root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error'
> > [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:16:45 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:15 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:16 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> > [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd A1, prog ata_id
> > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:34 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > [Sat Mar 6 21:18:55 2021] SCSI ioctl error, cmd 85, prog smartctl
> > [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> > [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> >
> > My linux-config and full dmesg-log are attached.
> >
>
> Checking dmesg again...
>
> So, this is pool-udisksd (cmd A1 and 85) and smartctl (cmd 85) causing
> regular xhci-resets.
>
> SCSI ioctl error, cmd 85, prog smartctl
>
> SCSI ioctl error, cmd A1, prog pool-udisksd
> SCSI ioctl error, cmd 85, prog pool-udisksd
>

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.

- Sedat -

2021-03-06 20:59:30

by Sedat Dilek

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

On Sat, Mar 6, 2021 at 9:49 PM Sedat Dilek <[email protected]> wrote:
>
> On Sat, Mar 6, 2021 at 9:38 PM Sedat Dilek <[email protected]> wrote:
> >
> > On Sat, Mar 6, 2021 at 9:26 PM Sedat Dilek <[email protected]> wrote:
> > >
> > > On Sat, Mar 6, 2021 at 5:58 PM Alan Stern <[email protected]> wrote:
> > > >
> > > > On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> > > > > No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:
> > > >
> > > > Is the kernel the only thing that is different? The rest of the
> > > > operating system and environment is exactly the same?
> > > >
> > > > > But I see there is already a quirk enabled and matches my ASmedia USB
> > > > > 3.0 controller (as I have *no* usb-storage-quirks enabled):
> > > > >
> > > > > root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> > > > > [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> > > > > 174c pid 55aa: 400000
> > > >
> > > > Yes, this is because that type of device already has a quirk entry built
> > > > into the kernel. You can find it by searching for "174c" in the kernel
> > > > source file drivers/usb/storage/unusual_devs.h.
> > > >
> > > > > Thanks Alan for all the hints and tips in the topic "usb-storage and
> > > > > quirks" and your patience.
> > > >
> > > > You can try building a 5.11 kernel with the patch below. I don't know
> > > > whether it will show anything in the dmesg log when one of these resets
> > > > occurs, but it might.
> > > >
> > > > If that doesn't work out, another possibility is to use git bisect to
> > > > find the commit between 5.10 and 5.11 which caused the problem to start.
> > > >
> > > > Alan Stern
> > > >
> > > >
> > > > --- usb-devel.orig/block/scsi_ioctl.c
> > > > +++ usb-devel/block/scsi_ioctl.c
> > > > @@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
> > > > hdr->host_status = host_byte(req->result);
> > > > hdr->driver_status = driver_byte(req->result);
> > > > hdr->info = 0;
> > > > - if (hdr->masked_status || hdr->host_status || hdr->driver_status)
> > > > + if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
> > > > hdr->info |= SG_INFO_CHECK;
> > > > + printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
> > > > + req->cmd[0], current->comm);
> > > > + }
> > > > hdr->resid = req->resid_len;
> > > > hdr->sb_len_wr = 0;
> > > >
> > > >
> > >
> > > Thanks for the diff, Alan.
> > >
> > > With an adapted version to fit Linux v5.12-rc2 (see attachment) I see:
> > >
> > > root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error'
> > > [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:16:45 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:15 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:16 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> > > [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:34 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > [Sat Mar 6 21:18:55 2021] SCSI ioctl error, cmd 85, prog smartctl
> > > [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> > > [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> > >
> > > My linux-config and full dmesg-log are attached.
> > >
> >
> > Checking dmesg again...
> >
> > So, this is pool-udisksd (cmd A1 and 85) and smartctl (cmd 85) causing
> > regular xhci-resets.
> >
> > SCSI ioctl error, cmd 85, prog smartctl
> >
> > SCSI ioctl error, cmd A1, prog pool-udisksd
> > SCSI ioctl error, cmd 85, prog pool-udisksd
> >
>
> 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.
>

These are the user-space programs:

root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error' | awk '{
print $11 " " $12 }' | sort -u
prog ata_id
prog hdparm
prog pool-udisksd
prog smartctl
prog smartd
prog udisksd

These are cmd #:

root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error' | awk '{
print $9 " " $10 }' | sort -u
cmd 85,
cmd A1,

- Sedat -

2021-03-06 21:07:22

by Sedat Dilek

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

On Sat, Mar 6, 2021 at 9:56 PM Sedat Dilek <[email protected]> wrote:
>
> On Sat, Mar 6, 2021 at 9:49 PM Sedat Dilek <[email protected]> wrote:
> >
> > On Sat, Mar 6, 2021 at 9:38 PM Sedat Dilek <[email protected]> wrote:
> > >
> > > On Sat, Mar 6, 2021 at 9:26 PM Sedat Dilek <[email protected]> wrote:
> > > >
> > > > On Sat, Mar 6, 2021 at 5:58 PM Alan Stern <[email protected]> wrote:
> > > > >
> > > > > On Sat, Mar 06, 2021 at 07:42:30AM +0100, Sedat Dilek wrote:
> > > > > > No, with Debian-Kernel 5.10.19-1 there are no xhci-resets:
> > > > >
> > > > > Is the kernel the only thing that is different? The rest of the
> > > > > operating system and environment is exactly the same?
> > > > >
> > > > > > But I see there is already a quirk enabled and matches my ASmedia USB
> > > > > > 3.0 controller (as I have *no* usb-storage-quirks enabled):
> > > > > >
> > > > > > root# LC_ALL=C dmesg -T | grep -i quirks | egrep '174c|55aa'
> > > > > > [Sat Mar 6 06:52:41 2021] usb-storage 4-1:1.0: Quirks match for vid
> > > > > > 174c pid 55aa: 400000
> > > > >
> > > > > Yes, this is because that type of device already has a quirk entry built
> > > > > into the kernel. You can find it by searching for "174c" in the kernel
> > > > > source file drivers/usb/storage/unusual_devs.h.
> > > > >
> > > > > > Thanks Alan for all the hints and tips in the topic "usb-storage and
> > > > > > quirks" and your patience.
> > > > >
> > > > > You can try building a 5.11 kernel with the patch below. I don't know
> > > > > whether it will show anything in the dmesg log when one of these resets
> > > > > occurs, but it might.
> > > > >
> > > > > If that doesn't work out, another possibility is to use git bisect to
> > > > > find the commit between 5.10 and 5.11 which caused the problem to start.
> > > > >
> > > > > Alan Stern
> > > > >
> > > > >
> > > > > --- usb-devel.orig/block/scsi_ioctl.c
> > > > > +++ usb-devel/block/scsi_ioctl.c
> > > > > @@ -258,8 +258,11 @@ static int blk_complete_sghdr_rq(struct
> > > > > hdr->host_status = host_byte(req->result);
> > > > > hdr->driver_status = driver_byte(req->result);
> > > > > hdr->info = 0;
> > > > > - if (hdr->masked_status || hdr->host_status || hdr->driver_status)
> > > > > + if (hdr->masked_status || hdr->host_status || hdr->driver_status) {
> > > > > hdr->info |= SG_INFO_CHECK;
> > > > > + printk(KERN_INFO "SCSI ioctl error, cmd %02X, prog %s\n",
> > > > > + req->cmd[0], current->comm);
> > > > > + }
> > > > > hdr->resid = req->resid_len;
> > > > > hdr->sb_len_wr = 0;
> > > > >
> > > > >
> > > >
> > > > Thanks for the diff, Alan.
> > > >
> > > > With an adapted version to fit Linux v5.12-rc2 (see attachment) I see:
> > > >
> > > > root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error'
> > > > [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:16:42 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:16:45 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:07 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:12 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:13 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:14 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:15 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:16 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:18 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:19 2021] SCSI ioctl error, cmd 85, prog smartd
> > > > [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:21 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd A1, prog ata_id
> > > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:22 2021] SCSI ioctl error, cmd 85, prog hdparm
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:28 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:30 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:34 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:35 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:36 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:37 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:38 2021] SCSI ioctl error, cmd 85, prog udisksd
> > > > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > > [Sat Mar 6 21:17:39 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd A1, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:17:40 2021] SCSI ioctl error, cmd 85, prog pool-udisksd
> > > > [Sat Mar 6 21:18:55 2021] SCSI ioctl error, cmd 85, prog smartctl
> > > > [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> > > > [Sat Mar 6 21:18:56 2021] SCSI ioctl error, cmd 85, prog smartctl
> > > >
> > > > My linux-config and full dmesg-log are attached.
> > > >
> > >
> > > Checking dmesg again...
> > >
> > > So, this is pool-udisksd (cmd A1 and 85) and smartctl (cmd 85) causing
> > > regular xhci-resets.
> > >
> > > SCSI ioctl error, cmd 85, prog smartctl
> > >
> > > SCSI ioctl error, cmd A1, prog pool-udisksd
> > > SCSI ioctl error, cmd 85, prog pool-udisksd
> > >
> >
> > 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.
> >
>
> These are the user-space programs:
>
> root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error' | awk '{
> print $11 " " $12 }' | sort -u
> prog ata_id
> prog hdparm
> prog pool-udisksd
> prog smartctl
> prog smartd
> prog udisksd
>
> These are cmd #:
>
> root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error' | awk '{
> print $9 " " $10 }' | sort -u
> cmd 85,
> cmd A1,
>

The combined list of cmd # and prog name might be more helpful:

root@iniza:~# LC_ALL=C dmesg -T | grep 'SCSI ioctl error' | awk '{
print $9 " " $10 " " $11 " " $12 }' | sort -u
cmd 85, prog hdparm
cmd 85, prog pool-udisksd
cmd 85, prog smartctl
cmd 85, prog smartd
cmd 85, prog udisksd
cmd A1, prog ata_id
cmd A1, prog pool-udisksd

- Sedat -

2021-03-08 02:29:26

by Alan Stern

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

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.

Alan Stern

2021-03-08 04:44:36

by Sedat Dilek

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

On Sun, Mar 7, 2021 at 4:46 PM Alan Stern <[email protected]> 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.

As said with Linux v5.10.y and Linux v5.11 I have not seen this.

What about CCing linux-block and linux-scsi people?

- Sedat -