search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.17k stars 5.01k forks source link

reset of high-speed USB device number x using dwc_otg resulting in I/O errors #5477

Open janvlug opened 1 year ago

janvlug commented 1 year ago

Describe the bug

I have a Raspberry Pi 3B+ where I want to have the rootfs on an external USB drive that is powered by its own power supply.

I can use the rootfs from the external USB drive, but I get these messages in the log:

usb 1-1.3: reset high-speed USB device number 5 using dwc_otg

which probably results in this type of errors:

I/O error, dev sda, sector 100665344 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2

Disk details: External WD Elements USB disk with its own power supply – WDBWLG0060HBK-XB

This disk is USB 2.0 compatible according to the product information.

I tried two different power supplies for the Raspberry Pi 3B+ (one of them the "offical" Raspberry power supply. With both power supplies I get the same errors.

When I still have the rootfs on the SD card I get no usb disconnects, nor I/O errors.

How followed the instructions on this site to copy the rootfs to the external USB HDD, but with some changes: I used the official standard Raspberry Pi image and a GPT partion table. The rootfs is ext4.

Steps to reproduce the behaviour

Configure the Raspberry Pi 3B+ to have the rootfs on the specified external USB HDD drive. Boot the system Observe the errors in the log

Device (s)

Raspberry Pi 3 Mod. B+

System

$ cat /etc/rpi-issue
Raspberry Pi reference 2023-05-03
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 47eee1f0ddcf8811559d51eea1c1bb48335e3e88, stage2
$ vcgencmd version
Mar 17 2023 10:52:42 
Copyright (c) 2012 Broadcom
version 82f3750a65fadae9a38077e3c2e217ad158c8d54 (clean) (release) (start)
$ uname -a
Linux raspberrypi 6.1.21-v7+ #1642 SMP Mon Apr  3 17:20:52 BST 2023 armv7l GNU/Linux

Logs

$ journalctl -b | grep -i "usb\|otg\|i\/o\|sda\|ready"
May 21 11:02:35 raspberrypi kernel: usbcore: registered new interface driver usbfs
May 21 11:02:35 raspberrypi kernel: usbcore: registered new interface driver hub
May 21 11:02:35 raspberrypi kernel: usbcore: registered new device driver usb
May 21 11:02:35 raspberrypi kernel: usb_phy_generic phy: supply vcc not found, using dummy regulator
May 21 11:02:35 raspberrypi kernel: usb_phy_generic phy: dummy supplies not allowed for exclusive requests
May 21 11:02:35 raspberrypi kernel: usbcore: registered new interface driver lan78xx
May 21 11:02:35 raspberrypi kernel: usbcore: registered new interface driver smsc95xx
May 21 11:02:35 raspberrypi kernel: dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
May 21 11:02:35 raspberrypi kernel: OTG VER PARAM: 0, OTG VER FLAG: 0
May 21 11:02:35 raspberrypi kernel: WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = 9ed04000 dma = 0xded04000 len=9024
May 21 11:02:35 raspberrypi kernel: dwc_otg: Microframe scheduler enabled
May 21 11:02:35 raspberrypi kernel: dwc_otg 3f980000.usb: DWC OTG Controller
May 21 11:02:35 raspberrypi kernel: dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
May 21 11:02:35 raspberrypi kernel: dwc_otg 3f980000.usb: irq 89, io mem 0x00000000
May 21 11:02:35 raspberrypi kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01
May 21 11:02:35 raspberrypi kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
May 21 11:02:35 raspberrypi kernel: usb usb1: Product: DWC OTG Controller
May 21 11:02:35 raspberrypi kernel: usb usb1: Manufacturer: Linux 6.1.21-v7+ dwc_otg_hcd
May 21 11:02:35 raspberrypi kernel: usb usb1: SerialNumber: 3f980000.usb
May 21 11:02:35 raspberrypi kernel: hub 1-0:1.0: USB hub found
May 21 11:02:35 raspberrypi kernel: dwc_otg: FIQ enabled
May 21 11:02:35 raspberrypi kernel: dwc_otg: NAK holdoff enabled
May 21 11:02:35 raspberrypi kernel: dwc_otg: FIQ split-transaction FSM enabled
May 21 11:02:35 raspberrypi kernel: usbcore: registered new interface driver usb-storage
May 21 11:02:35 raspberrypi kernel: usbcore: registered new interface driver usbhid
May 21 11:02:35 raspberrypi kernel: usbhid: USB HID core driver
May 21 11:02:35 raspberrypi kernel: usb 1-1: new high-speed USB device number 2 using dwc_otg
May 21 11:02:35 raspberrypi kernel: usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
May 21 11:02:35 raspberrypi kernel: usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
May 21 11:02:35 raspberrypi kernel: hub 1-1:1.0: USB hub found
May 21 11:02:35 raspberrypi kernel: usb 1-1.1: new high-speed USB device number 3 using dwc_otg
May 21 11:02:35 raspberrypi kernel: usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
May 21 11:02:35 raspberrypi kernel: usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
May 21 11:02:35 raspberrypi kernel: hub 1-1.1:1.0: USB hub found
May 21 11:02:35 raspberrypi kernel: usb 1-1.2: new full-speed USB device number 4 using dwc_otg
May 21 11:02:35 raspberrypi kernel: usb 1-1.2: New USB device found, idVendor=046d, idProduct=c52b, bcdDevice=12.11
May 21 11:02:35 raspberrypi kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May 21 11:02:35 raspberrypi kernel: usb 1-1.2: Product: USB Receiver
May 21 11:02:35 raspberrypi kernel: usb 1-1.2: Manufacturer: Logitech
May 21 11:02:35 raspberrypi kernel: input: Logitech USB Receiver as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/0003:046D:C52B.0001/input/input0
May 21 11:02:35 raspberrypi kernel: hid-generic 0003:046D:C52B.0001: input,hidraw0: USB HID v1.11 Keyboard [Logitech USB Receiver] on usb-3f980000.usb-1.2/input0
May 21 11:02:35 raspberrypi kernel: input: Logitech USB Receiver Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C52B.0002/input/input1
May 21 11:02:35 raspberrypi kernel: input: Logitech USB Receiver Consumer Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C52B.0002/input/input2
May 21 11:02:35 raspberrypi kernel: input: Logitech USB Receiver System Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C52B.0002/input/input3
May 21 11:02:35 raspberrypi kernel: hid-generic 0003:046D:C52B.0002: input,hiddev96,hidraw1: USB HID v1.11 Mouse [Logitech USB Receiver] on usb-3f980000.usb-1.2/input1
May 21 11:02:35 raspberrypi kernel: hid-generic 0003:046D:C52B.0003: hiddev97,hidraw2: USB HID v1.11 Device [Logitech USB Receiver] on usb-3f980000.usb-1.2/input2
May 21 11:02:35 raspberrypi kernel: usb 1-1.3: new high-speed USB device number 5 using dwc_otg
May 21 11:02:35 raspberrypi kernel: usb 1-1.3: New USB device found, idVendor=1058, idProduct=25a3, bcdDevice=10.31
May 21 11:02:35 raspberrypi kernel: usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 21 11:02:35 raspberrypi kernel: usb 1-1.3: Product: Elements 25A3
May 21 11:02:35 raspberrypi kernel: usb 1-1.3: Manufacturer: Western Digital
May 21 11:02:35 raspberrypi kernel: usb 1-1.3: SerialNumber: 575833324435313555325841
May 21 11:02:35 raspberrypi kernel: usb-storage 1-1.3:1.0: USB Mass Storage device detected
May 21 11:02:35 raspberrypi kernel: scsi host0: usb-storage 1-1.3:1.0
May 21 11:02:35 raspberrypi kernel: usb 1-1.1.1: new high-speed USB device number 6 using dwc_otg
May 21 11:02:35 raspberrypi kernel: usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
May 21 11:02:35 raspberrypi kernel: usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] Spinning up disk...
May 21 11:02:35 raspberrypi kernel: ........ready
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] Very big device. Trying to use READ CAPACITY(16).
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] 11720978432 512-byte logical blocks: (6.00 TB/5.46 TiB)
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] 4096-byte physical blocks
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] Write Protect is off
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] Mode Sense: 47 00 10 08
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] No Caching mode page found
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] Assuming drive cache: write through
May 21 11:02:35 raspberrypi kernel:  sda: sda1
May 21 11:02:35 raspberrypi kernel: sd 0:0:0:0: [sda] Attached SCSI disk
May 21 11:02:35 raspberrypi kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Quota mode: none.
May 21 11:02:49 raspberrypi kernel: EXT4-fs (sda1): re-mounted. Quota mode: none.
May 21 11:02:51 raspberrypi kernel: WARN::dwc_otg_hcd_urb_dequeue:639: Timed out waiting for FSM NP transfer to complete on 1
May 21 11:02:51 raspberrypi kernel: WARN::dwc_otg_hcd_urb_dequeue:639: Timed out waiting for FSM NP transfer to complete on 5
May 21 11:02:51 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:51 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:02:51 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 3d e0 00 00 00 28 00 00
May 21 11:02:51 raspberrypi kernel: I/O error, dev sda, sector 15840 op 0x0:(READ) flags 0x83700 phys_seg 5 prio class 2
May 21 11:02:53 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:53 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:02:53 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 06 00 08 00 00 00 00 08 00 00
May 21 11:02:53 raspberrypi kernel: I/O error, dev sda, sector 100665344 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2
May 21 11:02:54 raspberrypi mtp-probe[254]: checking bus 1, device 5: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3"
May 21 11:02:54 raspberrypi mtp-probe[252]: checking bus 1, device 4: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2"
May 21 11:02:54 raspberrypi mtp-probe[251]: checking bus 1, device 6: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.1"
May 21 11:02:54 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:54 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:55 raspberrypi kernel: usbcore: registered new interface driver uas
May 21 11:02:55 raspberrypi kernel: usbcore: registered new interface driver brcmfmac
May 21 11:02:56 raspberrypi kernel: logitech-djreceiver 0003:046D:C52B.0003: hiddev96,hidraw0: USB HID v1.11 Device [Logitech USB Receiver] on usb-3f980000.usb-1.2/input2
May 21 11:02:56 raspberrypi kernel: input: Logitech Wireless Device PID:4024 Keyboard as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.2/0003:046D:C52B.0003/0003:046D:4024.0004/input/input6
May 21 11:02:56 raspberrypi kernel: input: Logitech Wireless Device PID:4024 Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.2/0003:046D:C52B.0003/0003:046D:4024.0004/input/input7
May 21 11:02:56 raspberrypi kernel: hid-generic 0003:046D:4024.0004: input,hidraw1: USB HID v1.11 Keyboard [Logitech Wireless Device PID:4024] on usb-3f980000.usb-1.2/input2:1
May 21 11:02:56 raspberrypi kernel: input: Logitech Wireless Device PID:4090 Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.2/0003:046D:C52B.0003/0003:046D:4090.0005/input/input11
May 21 11:02:56 raspberrypi kernel: hid-generic 0003:046D:4090.0005: input,hidraw2: USB HID v1.11 Mouse [Logitech Wireless Device PID:4090] on usb-3f980000.usb-1.2/input2:2
May 21 11:02:57 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:57 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:02:57 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 10 00 08 00 00 00 00 08 00 00
May 21 11:02:57 raspberrypi kernel: I/O error, dev sda, sector 268437504 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2
May 21 11:02:58 raspberrypi kernel: input: Logitech K400 as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.2/0003:046D:C52B.0003/0003:046D:4024.0004/input/input15
May 21 11:02:58 raspberrypi kernel: logitech-hidpp-device 0003:046D:4024.0004: input,hidraw1: USB HID v1.11 Keyboard [Logitech K400] on usb-3f980000.usb-1.2/input2:1
May 21 11:02:58 raspberrypi kernel: input: Logitech MX Anywhere 3 as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.2/0003:046D:C52B.0003/0003:046D:4090.0005/input/input16
May 21 11:02:58 raspberrypi kernel: logitech-hidpp-device 0003:046D:4090.0005: input,hidraw2: USB HID v1.11 Mouse [Logitech MX Anywhere 3] on usb-3f980000.usb-1.2/input2:2
May 21 11:02:58 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:58 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:02:58 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 12 80 08 00 00 00 00 08 00 00
May 21 11:02:58 raspberrypi kernel: I/O error, dev sda, sector 310380544 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2
May 21 11:02:59 raspberrypi rngd[488]: entropy feed to the kernel ready
May 21 11:02:59 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:02:59 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:02:59 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 18 80 08 00 00 00 00 08 00 00
May 21 11:02:59 raspberrypi kernel: I/O error, dev sda, sector 411043840 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2
May 21 11:02:59 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:03:00 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:03:00 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 1b 00 08 00 00 00 00 08 00 00
May 21 11:03:00 raspberrypi kernel: I/O error, dev sda, sector 452986880 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2
May 21 11:03:00 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:03:00 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:03:00 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 1b 40 08 00 00 00 00 08 00 00
May 21 11:03:00 raspberrypi kernel: I/O error, dev sda, sector 457181184 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2
May 21 11:03:00 raspberrypi kernel: usb 1-1.3: reset high-speed USB device number 5 using dwc_otg
May 21 11:03:00 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=DRIVER_OK cmd_age=0s
May 21 11:03:00 raspberrypi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 1d 40 08 00 00 00 00 08 00 00
May 21 11:03:00 raspberrypi kernel: I/O error, dev sda, sector 490735616 op 0x0:(READ) flags 0x83700 phys_seg 1 prio class 2

Additional context

No response

janvlug commented 1 year ago

I left the Raspberry Pi 3 B+ running for 18 days, and only saw I/O errors during the boot phase. Note that I did not do any work on the Raspberry Pi during these 18 days, so maybe there were no I/O errors because the disk access was probably close to zero.