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.03k stars 4.95k forks source link

[USB VL805 RPI4] Unexpected USB ports failure during high speed USB transfer from Kingston MobileLite Plus USB3.2 card reader #5980

Open qrp73 opened 6 months ago

qrp73 commented 6 months ago

Describe the bug

I'm copied data from sdcard using Kingston MobileLite Plus USB3.2 UHS-II micriSD card reader. In background RTLSDR dongle was used. At some point some unexpected sdcard read failure occurs (the card is ok and reading ok), RTLSDR also stopped to work and disappears from tree. After that I reconnected RTLSDR and card reader both are detected ok. But when I started f3write test it fails to write at second file.

After reboot all works ok.

I'm using this USB card reader: https://www.aliexpress.com/item/1005004681111603.html

Steps to reproduce the behaviour

Updated: here is steps to reproduce:

1) Install Kingston MobileLite Plus USB3.2 UHS-II micriSD card reader (I bought it here: https://www.aliexpress.com/item/1005004681111603.html) 2) Put Samsung EVO A1 64GB sdcard (I bought it here: https://www.aliexpress.com/item/1005005744366645.html) 3) Run f3write to write test sequence on sdcard 4) Run f3read to read and check the data

Expected result: f3write and f3read is done with no errors

Actual result: I/O error occurs during f3read operation at random position

Device (s)

Raspberry Pi 4 Mod. B

System

$ cat /etc/rpi-issue Raspberry Pi reference 2023-09-22 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 40f37458ae7cadea1aec913ae10b5e7008ebce0a, stage4

$ vcgencmd version Dec 8 2023 12:36:15 Copyright (c) 2012 Broadcom version e02d33b3122450accf9dea471a177d3b5623f5ad (clean) (release) (start)

$ uname -a Linux raspi 6.6.17-v8+ #1 SMP PREEMPT Mon Feb 19 12:11:19 UTC 2024 aarch64 GNU/Linux

Logs

Feb 22 20:44:39 raspi kernel: usb 2-1: new SuperSpeed USB device number 5 using xhci_hcd
Feb 22 20:44:39 raspi kernel: usb 2-1: New USB device found, idVendor=11b0, idProduct=3307, bcdDevice= 0.14
Feb 22 20:44:39 raspi kernel: usb 2-1: New USB device strings: Mfr=3, Product=4, SerialNumber=2
Feb 22 20:44:39 raspi kernel: usb 2-1: Product: UHSII uSD Reader
Feb 22 20:44:39 raspi kernel: usb 2-1: Manufacturer: Kingston
Feb 22 20:44:39 raspi kernel: usb 2-1: SerialNumber: 2021050000****
Feb 22 20:44:39 raspi kernel: usb-storage 2-1:1.0: USB Mass Storage device detected
Feb 22 20:44:39 raspi kernel: scsi host0: usb-storage 2-1:1.0
Feb 22 20:44:39 raspi mtp-probe[359887]: checking bus 2, device 5: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb2/2-1"
Feb 22 20:44:39 raspi mtp-probe[359887]: bus: 2, device: 5 was not an MTP device
Feb 22 20:44:39 raspi mtp-probe[359897]: checking bus 2, device 5: "/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb2/2-1"
Feb 22 20:44:39 raspi mtp-probe[359897]: bus: 2, device: 5 was not an MTP device
Feb 22 20:44:40 raspi kernel: scsi 0:0:0:0: Direct-Access     Kingston UHSII uSD Reader 0014 PQ: 0 ANSI: 6
Feb 22 20:44:40 raspi kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0
Feb 22 20:44:41 raspi kernel: sd 0:0:0:0: [sda] Spinning up disk...
Feb 22 20:44:44 raspi kernel: ..
Feb 22 20:44:44 raspi kernel: sd 0:0:0:0: [sda] Media removed, stopped polling
Feb 22 20:44:44 raspi kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk
Feb 22 20:44:49 raspi kernel: sd 0:0:0:0: [sda] 61067264 512-byte logical blocks: (31.3 GB/29.1 GiB)
Feb 22 20:44:49 raspi kernel: sda: detected capacity change from 0 to 61067264
Feb 22 20:44:49 raspi kernel:  sda: sda1
Feb 22 20:44:50 raspi kernel: EXT4-fs (sda1): mounted filesystem 9aee****-42f6-4063-b7ac-707944b**** r/w with ordered data mode. Quota mode: none.
Feb 22 20:44:50 raspi udisksd[636]: Mounted /dev/sda1 at /media/pi/arch-usb2023 on behalf of uid 1000
Feb 22 20:45:00 raspi xdg-desktop-por[1309]: A backend call failed: Inhibiting other than idle not supported
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 01 08 00 00 f8 00
Feb 22 20:45:34 raspi kernel: I/O error, dev sda, sector 264 op 0x0:(READ) flags 0x80700 phys_seg 31 prio class 2
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 01 08 00 00 08 00
Feb 22 20:45:34 raspi kernel: I/O error, dev sda, sector 264 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
Feb 22 20:45:34 raspi kernel: Buffer I/O error on dev sda, logical block 33, async page read
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 01 08 00 00 08 00
Feb 22 20:45:34 raspi kernel: I/O error, dev sda, sector 264 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
Feb 22 20:45:34 raspi kernel: Buffer I/O error on dev sda, logical block 33, async page read
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 01 08 00 00 08 00
Feb 22 20:45:34 raspi kernel: I/O error, dev sda, sector 264 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
Feb 22 20:45:34 raspi kernel: Buffer I/O error on dev sda, logical block 33, async page read
Feb 22 20:45:34 raspi kernel: sda: detected capacity change from 61067264 to 0
Feb 22 20:45:34 raspi udisksd[636]: Cleaning up mount point /media/pi/arch-usb2023 (device 8:1 no longer exists)
Feb 22 20:45:34 raspi kernel: EXT4-fs (sda1): unmounting filesystem 9aee****-42f6-4063-b7ac-707944be****.
Feb 22 20:45:34 raspi systemd[1]: media-pi-arch\x2dusb2023.mount: Deactivated successfully.
Feb 22 20:45:34 raspi kernel: sd 0:0:0:0: [sda] tag#0 access beyond end of device
Feb 22 20:45:34 raspi kernel: I/O error, dev sda, sector 2048 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 2
Feb 22 20:45:34 raspi kernel: Buffer I/O error on dev sda1, logical block 0, lost sync page write
Feb 22 20:45:34 raspi kernel: EXT4-fs (sda1): I/O error while writing superblock
Feb 22 20:46:24 raspi kernel: usb 1-1.4.1: USB disconnect, device number 9
Feb 22 20:46:56 raspi kernel: sd 0:0:0:0: [sda] 15523840 512-byte logical blocks: (7.95 GB/7.40 GiB)
Feb 22 20:46:56 raspi kernel: sda: detected capacity change from 0 to 15523840
Feb 22 20:46:56 raspi kernel:  sda: sda1
Feb 22 20:46:56 raspi kernel: FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Feb 22 20:46:56 raspi udisksd[636]: Mounted /dev/sda1 at /media/pi/****-0064 on behalf of uid 1000
Feb 22 20:47:07 raspi xdg-desktop-por[1309]: A backend call failed: Inhibiting other than idle not supported

Additional context

This issue may be related with this one: https://github.com/raspberrypi/linux/issues/5926

It has very different log errors, but there is definitely some critical bug in USB driver for RPI4 VL805 chip which cause a lot of USB failure errors.

P33M commented 6 months ago

Explain to me how this is not a duplicate of your other complaints about the VL805.

qrp73 commented 6 months ago

The log errors for this issue are completely different and it don't turn all USB ports into unrecoverable state, like it happens for https://github.com/raspberrypi/linux/issues/5926.

It appears that I can reproduce this issue. I tried to to f3write and f3read on this card reader for Samsung EVO A1 64GB sdcard and it leads to transfer error at random block in the middle of sdcard (the card is ok and it works ok on PC with the same sdcard reader).

It looks like this is a new issue related to high speed transfer or with supporting this sdcard reader. I just got this new sdcard reader, it works extremely fast and reads sdcard with max speed that it supports (130 MB/s for Samsung EVO A1). So, the very high transfer speed may be the reason for this issue.

But it also may be related with issue #5926. Needs investigation.

Here is the result:

$ f3read /media/pi/9C33-6BBD/
F3 read 8.0
Copyright (C) 2010 Digirati Internet LTDA.
This is free software; see the source for copying conditions.

                  SECTORS      ok/corrupted/changed/overwritten
Validating file 1.h2w ... 2097152/        0/      0/      0
Validating file 2.h2w ... 2097152/        0/      0/      0
Validating file 3.h2w ... 2097152/        0/      0/      0
Validating file 4.h2w ... 2097152/        0/      0/      0
Validating file 5.h2w ... 2097152/        0/      0/      0
Validating file 6.h2w ... 2097152/        0/      0/      0
Validating file 7.h2w ... 2097152/        0/      0/      0
Validating file 8.h2w ... 2097152/        0/      0/      0
Validating file 9.h2w ... 2097152/        0/      0/      0
Validating file 10.h2w ... 2097152/        0/      0/      0
Validating file 11.h2w ... 2097152/        0/      0/      0
Validating file 12.h2w ... 2097152/        0/      0/      0
Validating file 13.h2w ... 2097152/        0/      0/      0
Validating file 14.h2w ... 2097152/        0/      0/      0
Validating file 15.h2w ... 2097152/        0/      0/      0
Validating file 16.h2w ... 2097152/        0/      0/      0
Validating file 17.h2w ... 2097152/        0/      0/      0
Validating file 18.h2w ... 2097152/        0/      0/      0
Validating file 19.h2w ... 2097152/        0/      0/      0
Validating file 20.h2w ... 2097152/        0/      0/      0
Validating file 21.h2w ... 2097152/        0/      0/      0
Validating file 22.h2w ... 2097152/        0/      0/      0
Validating file 23.h2w ... 2097152/        0/      0/      0
Validating file 24.h2w ... 2097152/        0/      0/      0
Validating file 25.h2w ... 2097152/        0/      0/      0
Validating file 26.h2w ... 2097152/        0/      0/      0
Validating file 27.h2w ... 2097152/        0/      0/      0
Validating file 28.h2w ... 2097152/        0/      0/      0
Validating file 29.h2w ... 2097152/        0/      0/      0
Validating file 30.h2w ... 2097152/        0/      0/      0
Validating file 31.h2w ... 2097152/        0/      0/      0
Validating file 32.h2w ... 2097152/        0/      0/      0
Validating file 33.h2w ... 2097152/        0/      0/      0
Validating file 34.h2w ... 2097152/        0/      0/      0
Validating file 35.h2w ... 2097152/        0/      0/      0
Validating file 36.h2w ... 2097152/        0/      0/      0
Validating file 37.h2w ... 2097152/        0/      0/      0
Validating file 38.h2w ... 2097152/        0/      0/      0
Validating file 39.h2w ... 2097152/        0/      0/      0
Validating file 40.h2w ... 2097152/        0/      0/      0
Validating file 41.h2w ... 2097152/        0/      0/      0
Validating file 42.h2w ... 2097152/        0/      0/      0
Validating file 43.h2w ... 2097152/        0/      0/      0
Validating file 44.h2w ... 2097152/        0/      0/      0
Validating file 45.h2w ... 2097152/        0/      0/      0
Validating file 46.h2w ... 2097152/        0/      0/      0
Validating file 47.h2w ... 2097152/        0/      0/      0
Validating file 48.h2w ... 2097152/        0/      0/      0
Validating file 49.h2w ... 1793809/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 50.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 51.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 52.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 53.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 54.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 55.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 56.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 57.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 58.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 59.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 60.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"

  Data OK: 48.86 GB (102457105 sectors)
Data LOST: 0.00 Byte (0 sectors)
           Corrupted: 0.00 Byte (0 sectors)
    Slightly changed: 0.00 Byte (0 sectors)
         Overwritten: 0.00 Byte (0 sectors)
WARNING: Not all data was read due to I/O error(s)
Average reading speed: 124.97 MB/s

$ f3read /media/pi/9C33-6BBD/
F3 read 8.0
Copyright (C) 2010 Digirati Internet LTDA.
This is free software; see the source for copying conditions.

                  SECTORS      ok/corrupted/changed/overwritten
Validating file 1.h2w ... 2097152/        0/      0/      0
Validating file 2.h2w ... 2097152/        0/      0/      0
Validating file 3.h2w ... 2097152/        0/      0/      0
Validating file 4.h2w ... 2097152/        0/      0/      0
Validating file 5.h2w ... 2097152/        0/      0/      0
Validating file 6.h2w ... 2097152/        0/      0/      0
Validating file 7.h2w ... 2097152/        0/      0/      0
Validating file 8.h2w ... 2097152/        0/      0/      0
Validating file 9.h2w ... 2097152/        0/      0/      0
Validating file 10.h2w ... 2097152/        0/      0/      0
Validating file 11.h2w ... 2097152/        0/      0/      0
Validating file 12.h2w ... 2097152/        0/      0/      0
Validating file 13.h2w ... 2097152/        0/      0/      0
Validating file 14.h2w ... 2097152/        0/      0/      0
Validating file 15.h2w ... 2097152/        0/      0/      0
Validating file 16.h2w ... 2097152/        0/      0/      0
Validating file 17.h2w ... 2097152/        0/      0/      0
Validating file 18.h2w ... 2097152/        0/      0/      0
Validating file 19.h2w ... 2097152/        0/      0/      0
Validating file 20.h2w ... 2097152/        0/      0/      0
Validating file 21.h2w ... 2097152/        0/      0/      0
Validating file 22.h2w ... 2097152/        0/      0/      0
Validating file 23.h2w ... 2097152/        0/      0/      0
Validating file 24.h2w ... 2097152/        0/      0/      0
Validating file 25.h2w ... 2097152/        0/      0/      0
Validating file 26.h2w ... 2097152/        0/      0/      0
Validating file 27.h2w ... 2097152/        0/      0/      0
Validating file 28.h2w ... 2097152/        0/      0/      0
Validating file 29.h2w ...  176128/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 30.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 31.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 32.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 33.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 34.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 35.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 36.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 37.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 38.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 39.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 40.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 41.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 42.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 43.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 44.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 45.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 46.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 47.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 48.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 49.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 50.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 51.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 52.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 53.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 54.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 55.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 56.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 57.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 58.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 59.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 60.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"

  Data OK: 28.08 GB (58896384 sectors)
Data LOST: 0.00 Byte (0 sectors)
           Corrupted: 0.00 Byte (0 sectors)
    Slightly changed: 0.00 Byte (0 sectors)
         Overwritten: 0.00 Byte (0 sectors)
WARNING: Not all data was read due to I/O error(s)
Average reading speed: 127.61 MB/s

The log file:

[   77.972531] usb 2-1: new SuperSpeed USB device number 3 using xhci_hcd
[   77.995965] usb 2-1: New USB device found, idVendor=11b0, idProduct=3307, bcdDevice= 0.14
[   77.995991] usb 2-1: New USB device strings: Mfr=3, Product=4, SerialNumber=2
[   77.996003] usb 2-1: Product: UHSII uSD Reader
[   77.996014] usb 2-1: Manufacturer: Kingston
[   77.996023] usb 2-1: SerialNumber: 2021050000****
[   78.004313] usb-storage 2-1:1.0: USB Mass Storage device detected
[   78.008939] scsi host0: usb-storage 2-1:1.0
[   79.015178] scsi 0:0:0:0: Direct-Access     Kingston UHSII uSD Reader 0014 PQ: 0 ANSI: 6
[   79.017113] sd 0:0:0:0: Attached scsi generic sg0 type 0
[   79.585676] sd 0:0:0:0: [sda] 125173760 512-byte logical blocks: (64.1 GB/59.7 GiB)
[   79.586670] sd 0:0:0:0: [sda] Write Protect is off
[   79.586687] sd 0:0:0:0: [sda] Mode Sense: 21 00 00 00
[   79.587664] sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[   79.605932]  sda: sda1
[   79.606514] sd 0:0:0:0: [sda] Attached SCSI removable disk
[   79.914115] exFAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[ 2538.245684] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 2538.245711] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 2538.245721] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 2538.245739] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 06 1c 71 00 00 02 00 00
[ 2538.245749] I/O error, dev sda, sector 102527232 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 2
[ 2538.247426] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 2538.247440] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 2538.247449] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 2538.247459] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 06 1c 73 00 00 02 00 00
[ 2538.247465] I/O error, dev sda, sector 102527744 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 2
[ 2538.741153] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 2538.741182] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x6 [current] 
[ 2538.741194] sd 0:0:0:0: [sda] tag#0 ASC=0x28 ASCQ=0x0 
[ 2538.741209] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 06 1c 71 00 00 00 08 00
[ 2538.741218] I/O error, dev sda, sector 102527232 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 2538.741399] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.741418] I/O error, dev sda, sector 102527232 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 2538.742878] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.742906] I/O error, dev sda, sector 102826752 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 2
[ 2538.743022] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.743035] I/O error, dev sda, sector 102826752 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 2538.743587] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.743604] I/O error, dev sda, sector 104923904 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 2
[ 2538.743672] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.743684] I/O error, dev sda, sector 104923904 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 2538.744219] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.744236] I/O error, dev sda, sector 107021056 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 2
[ 2538.744307] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.744318] I/O error, dev sda, sector 107021056 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 2538.744828] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.744896] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.745402] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.745468] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.746084] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.746184] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.746643] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.746712] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.747248] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.747317] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.747835] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.747902] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.748419] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.748485] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.748981] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2538.749044] sd 0:0:0:0: [sda] tag#0 device offline or changed
[ 2543.610746] sda: detected capacity change from 125173760 to 0
[ 2549.676671] sd 0:0:0:0: [sda] 125173760 512-byte logical blocks: (64.1 GB/59.7 GiB)
[ 2549.678729] sda: detected capacity change from 0 to 125173760
[ 2549.679707]  sda: sda1
[ 2549.962578] exFAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[ 4526.195483] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.195514] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.195526] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.195540] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 83 bb 00 00 02 00 00
[ 4526.195549] blk_print_req_error: 16 callbacks suppressed
[ 4526.195557] I/O error, dev sda, sector 58964736 op 0x0:(READ) flags 0x80700 phys_seg 8 prio class 2
[ 4526.197351] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.197370] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.197380] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.197392] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 83 bd 00 00 02 00 00
[ 4526.197400] I/O error, dev sda, sector 58965248 op 0x0:(READ) flags 0x80700 phys_seg 8 prio class 2
[ 4526.199158] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.199185] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.199197] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.199209] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 83 bb 00 00 00 08 00
[ 4526.199218] I/O error, dev sda, sector 58964736 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4526.201064] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.201084] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.201096] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.201109] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 83 bb 00 00 00 08 00
[ 4526.201118] I/O error, dev sda, sector 58964736 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4526.203562] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.203584] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.203596] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.203611] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 a1 03 00 00 02 00 00
[ 4526.203622] I/O error, dev sda, sector 60883712 op 0x0:(READ) flags 0x80700 phys_seg 9 prio class 2
[ 4526.205469] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.205492] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.205503] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.205516] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 a1 03 00 00 00 08 00
[ 4526.205524] I/O error, dev sda, sector 60883712 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4526.207841] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.207863] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.207874] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.207889] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 c1 03 00 00 02 00 00
[ 4526.207899] I/O error, dev sda, sector 62980864 op 0x0:(READ) flags 0x80700 phys_seg 11 prio class 2
[ 4526.209706] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.209729] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.209739] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.209752] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 c1 03 00 00 00 08 00
[ 4526.209761] I/O error, dev sda, sector 62980864 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4526.213539] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.213569] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.213582] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.213599] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 e1 03 00 00 02 00 00
[ 4526.213611] I/O error, dev sda, sector 65078016 op 0x0:(READ) flags 0x80700 phys_seg 10 prio class 2
[ 4526.215556] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s
[ 4526.215585] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x2 [current] 
[ 4526.215597] sd 0:0:0:0: [sda] tag#0 ASC=0x3a ASCQ=0x0 
[ 4526.215613] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 03 e1 03 00 00 00 08 00
[ 4526.215624] I/O error, dev sda, sector 65078016 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
qrp73 commented 6 months ago

To make sure that this issue is not related to the card reader or sdcard hardware, I just tested it on x86-64 PC with f3write and then f3read. On PC it works ok with no errors.

Next, I disconnected all USB devices from RPI4 except mouse and keyboard and connected card reader with the same sdcard and run f3read. It fails:

$ lsusb
Bus 002 Device 002: ID 11b0:3307 ATECH FLASH TECHNOLOGY UHSII uSD Reader
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 006: ID 1c4f:0026 SiGma Micro Keyboard
Bus 001 Device 005: ID 046d:c051 Logitech, Inc. G3 (MX518) Optical Mouse
Bus 001 Device 003: ID 214b:7250 Huasheng Electronics USB2.0 HUB
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

$ f3read /media/pi/9C33-6BBD/
F3 read 8.0
Copyright (C) 2010 Digirati Internet LTDA.
This is free software; see the source for copying conditions.

                  SECTORS      ok/corrupted/changed/overwritten
Validating file 1.h2w ... 2097152/        0/      0/      0
Validating file 2.h2w ... 2097152/        0/      0/      0
Validating file 3.h2w ... 2097152/        0/      0/      0
Validating file 4.h2w ... 2097152/        0/      0/      0
Validating file 5.h2w ... 2097152/        0/      0/      0
Validating file 6.h2w ... 2097152/        0/      0/      0
Validating file 7.h2w ... 2097152/        0/      0/      0
Validating file 8.h2w ... 2097152/        0/      0/      0
Validating file 9.h2w ... 2097152/        0/      0/      0
Validating file 10.h2w ... 2097152/        0/      0/      0
Validating file 11.h2w ... 2097152/        0/      0/      0
Validating file 12.h2w ... 2097152/        0/      0/      0
Validating file 13.h2w ... 2097152/        0/      0/      0
Validating file 14.h2w ... 2097152/        0/      0/      0
Validating file 15.h2w ... 2097152/        0/      0/      0
Validating file 16.h2w ... 2097152/        0/      0/      0
Validating file 17.h2w ... 2097152/        0/      0/      0
Validating file 18.h2w ... 2097152/        0/      0/      0
Validating file 19.h2w ... 2097152/        0/      0/      0
Validating file 20.h2w ... 2097152/        0/      0/      0
Validating file 21.h2w ... 2097152/        0/      0/      0
Validating file 22.h2w ... 2097152/        0/      0/      0
Validating file 23.h2w ... 2097152/        0/      0/      0
Validating file 24.h2w ... 2097152/        0/      0/      0
Validating file 25.h2w ... 2097152/        0/      0/      0
Validating file 26.h2w ... 2097152/        0/      0/      0
Validating file 27.h2w ... 2097152/        0/      0/      0
Validating file 28.h2w ... 2097152/        0/      0/      0
Validating file 29.h2w ... 2097152/        0/      0/      0
Validating file 30.h2w ... 2097152/        0/      0/      0
Validating file 31.h2w ... 2097152/        0/      0/      0
Validating file 32.h2w ... 2097152/        0/      0/      0
Validating file 33.h2w ... 2097152/        0/      0/      0
Validating file 34.h2w ... 2097152/        0/      0/      0
Validating file 35.h2w ... 2097152/        0/      0/      0
Validating file 36.h2w ... 2097152/        0/      0/      0
Validating file 37.h2w ...   16384/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 38.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 39.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 40.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 41.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 42.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 43.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 44.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 45.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 46.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 47.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 48.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 49.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 50.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 51.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 52.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 53.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 54.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 55.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 56.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 57.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 58.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 59.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"
Validating file 60.h2w ...       0/        0/      0/      0 - NOT fully read due to "Input/output error"

  Data OK: 36.01 GB (75513856 sectors)
Data LOST: 0.00 Byte (0 sectors)
           Corrupted: 0.00 Byte (0 sectors)
    Slightly changed: 0.00 Byte (0 sectors)
         Overwritten: 0.00 Byte (0 sectors)
WARNING: Not all data was read due to I/O error(s)
Average reading speed: 126.47 MB/s

So, you can reproduce this issue in the following way: 1) Install Kingston MobileLite Plus USB3.2 UHS-II micriSD card reader (I bought it here: https://www.aliexpress.com/item/1005004681111603.html) 2) Put Samsung EVO A1 64GB sdcard (I bought it here: https://www.aliexpress.com/item/1005005744366645.html) 3) Run f3write and for write test sequence on sdcard 4) Run f3read to read and check the data

Expected result: f3write and f3read is done with no errors

Actual result: I/O error occurs during f3read operation at random position

qrp73 commented 6 months ago

I tested this issue on old snapshot of Raspberry Pi OS Bullseye and I can reproduce it on Bullseye.

It seems that I found the root of cause for this issue... I'm using genuine Raspberry Pi 15W PSU (MODEL KSA-15E-051300HE) it has 5.2 V on the output. So I suspect this issue may be related with overvoltage, so I powered my RPI4 from power bank which provides 5.05V on the output and this issue disappears... When RPI4 is powered from power bank it passed f3read test several times with no issue.

This is the second issue with genuine Raspberry Pi 15W PSU, previously it damage my USB sound DAC due to missing mains grounding (the ground pin of genuine RPI PSU has 90V AC potential relative to equipment with proper ground terminal on its mains connector, this issue is present on all genuine RPI PSU).

Currently I'm testing it to clarify that PSU overvoltage is really the root of cause for this issue.

Here is my PSU: photo

JamesH65 commented 6 months ago

I doubt this has anything to do with any overvoltage. If you measure the 5v on the board itself, it will read about 5v. The PS is 5.1v to compensate for power loss over the cabling. The Pi PS are extremely well designed and manufactured parts.

JamesH65 commented 6 months ago

I did a little more digging into the second point you made, and have this response from a power supply expert.

"The output of the PSU does float with reference to the main and you will see a voltage with reference to the mains. The current is very low. This is standard in the industry for laptops and many phones chargers etc. The outer shell of the type C connector connects first to the system ground when plugged in and therefore there should be no damage as the system ground is all at the same potential. If the USB DAC fails due to this then it suggests there might be another issue."

6by9 commented 6 months ago

"The output of the PSU does float with reference to the main and you will see a voltage with reference to the mains. The current is very low. This is standard in the industry for laptops and many phones chargers etc. The outer shell of the type C connector connects first to the system ground when plugged in and therefore there should be no damage as the system ground is all at the same potential. If the USB DAC fails due to this then it suggests there might be another issue."

The official classification is as a Class II appliance (aka double insulated) normally denoted by the Square in a square symbol https://en.wikipedia.org/wiki/Appliance_classes#Class_II

qrp73 commented 6 months ago

I doubt this has anything to do with any overvoltage. If you measure the 5v on the board itself, it will read about 5v. The PS is 5.1v to compensate for power loss over the cabling. The Pi PS are extremely well designed and manufactured parts.

I still not sure if it happens due to overvoltage. Needs more testing. Today the issue disappears and f3read test is passed with no errors. But yesterday I can reproduce it several times, I tried reconnect all things and it was stable reproduced.

I'm not sure what happens today. I see that current mains voltage is dropped down to 215-222 V, usually it is 230-240V, so it may be related. Needs to wait some time when mains voltage rise up.

Currently RPI PSU provide 5.05-5.15V and USB works ok, f3read passed with no issue. Currently I'm testing it with different conditions to find the root of cause of the issue.

"The output of the PSU does float with reference to the main and you will see a voltage with reference to the mains. The current is very low. This is standard in the industry for laptops and many phones chargers etc. The outer shell of the type C connector connects first to the system ground when plugged in and therefore there should be no damage as the system ground is all at the same potential. If the USB DAC fails due to this then it suggests there might be another issue."

The problem happens when I connected audio cable through 3.5mm connector to USB DAC and all devices with proper grounding was disconnected (include hdmi). Since all devices with proper grounding was disconnected, RPI GND has floating 90V AC potential relative to ground (measured with DMM). Even if current is limited with capacitor, high voltage still can damage sensitive semiconductors, for example output transistors.

The audio cable was connected to a power amplifier which has proper grounding terminal on mains connector, so there is 90V AC between audio cable GND and RPI GND. And during audio cable connection it leads to damage for output circuit of USB DAC. I don't know what happens to it exatly, looks like a overvoltage breakdown of the output transistors. USB DAC still worked, but has distorted output with high noise after that.

Usually I have HDMI cable connected from display which has proper ground terminal on mains connector, so it worked like ground for RPI through hdmi cable and all worked ok. But since it was disconnected, it leads to USB DAC damage during audio cable connection. This is how it happens.

pelwell commented 6 months ago

I still say that using a powered hub, rather than expecting the Pi to route sufficient power out of its USB ports, would probably solve your problems.

qrp73 commented 6 months ago

I still say that using a powered hub, rather than expecting the Pi to route sufficient power out of its USB ports, would probably solve your problems.

There is no undervoltage, I connected DMM in min/max tracking mode to RPI USB connector. Disconnected card reader: 5.1155V Connected card reader (idle): 5.1070V Connected card reader (f3read at 130 MB/s): 5.0693V

The minimum registered voltage drop: 5.0333V

But currently I cannot reproduce the issue. Still testing it, DMM is connected so if it happens I can see if there is change for voltage.

pelwell commented 6 months ago

This is only measuring the voltage at one place. It helps to picture the voltage in the system as the depth of water in a bath, etc., as multiple plugs are inserted and removed in real time. The water level will not be uniform across the surface, with a number of local minima. Ring oscillators give us more of an idea of the voltage at various points within the SoC, but even that doesn't cover the VL805.

My point is that you've invested a lot of time into reporting this problem across a number of threads, and this is one obvious avenue you seem reluctant to explore.

qrp73 commented 6 months ago

This is strange, but issue disappears. I'm not sure why. I suspect it may be due to bad contacts on sdcard. Needs more testing.

qrp73 commented 5 months ago

Probably the root of cause is a bad contact between the reader and sdcard. Sometimes the issue can be reproduced, but when I reinsert the card it disappears.