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

kernel: 4.19.83, 5.3.11, 5.4.3 reports wrongly SSD disk capacity (130PB instead of 512GB) #3388

Open dwrobel opened 4 years ago

dwrobel commented 4 years ago

While attaching SSD disk through the USB 3.0 controller to the RPi4 or RPi3B+ they reports the wrong size of the disk capacity and as a result they can't read properly disk partition layout.

dmesg excerpt while connecting to the RPi4 (kernel 4.19.83):

[  235.508847] usb 1-1.3: USB disconnect, device number 3
[  254.054263] usb 2-2: new SuperSpeed Gen 1 USB device number 3 using xhci_hcd
[  254.095129] usb 2-2: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[  254.109673] usb 2-2: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[  254.123089] usb 2-2: Product: ASMT1153e
[  254.133191] usb 2-2: Manufacturer: asmedia
[  254.143607] usb 2-2: SerialNumber: 123456789299
[  254.159452] usb-storage 2-2:1.0: USB Mass Storage device detected
[  254.170292] usb-storage 2-2:1.0: Quirks match for vid 174c pid 55aa: 400000
[  254.181866] scsi host0: usb-storage 2-2:1.0
[  259.028214] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[  259.047811] sd 0:0:0:0: [sda] 253657636776757 512-byte logical blocks: (130 PB/115 PiB)
[  259.061907] sd 0:0:0:0: [sda] Write Protect is off
[  259.071829] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[  259.072439] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  269.400213] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[  269.414935] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[  269.430700] print_req_error: I/O error, dev sda, sector 0
[  269.442929] buffer_io_error: 14 callbacks suppressed
[  269.442938] Buffer I/O error on dev sda, logical block 0, async page read
[  279.751403] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[  279.766522] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 01 00 00 00 07 00 00
[  279.782771] print_req_error: I/O error, dev sda, sector 1
[  279.795561] Buffer I/O error on dev sda, logical block 1, async page read
[  279.809869] Buffer I/O error on dev sda, logical block 2, async page read
[  279.824077] Buffer I/O error on dev sda, logical block 3, async page read
[  279.838129] Buffer I/O error on dev sda, logical block 4, async page read
[  279.851943] Buffer I/O error on dev sda, logical block 5, async page read
[  279.865623] Buffer I/O error on dev sda, logical block 6, async page read
[  279.879313] Buffer I/O error on dev sda, logical block 7, async page read

I don't have access to other types of RPi(s) to test them.

However, when I'm connecting the same disk, using the same USB controller, to the x8664 based PC machine (kernel 5.4.5)_ the relevant dmesg excerpt looks like the following:

[119904.472199] usb 1-8: USB disconnect, device number 6
[122144.357261] usb 2-2: new SuperSpeed Gen 1 USB device number 3 using xhci_hcd
[122144.370242] usb 2-2: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[122144.370246] usb 2-2: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[122144.370249] usb 2-2: Product: ASMT1153e
[122144.370252] usb 2-2: Manufacturer: asmedia
[122144.370254] usb 2-2: SerialNumber: 123456789299
[122144.371956] usb-storage 2-2:1.0: USB Mass Storage device detected
[122144.372306] usb-storage 2-2:1.0: Quirks match for vid 174c pid 55aa: 400000
[122144.372363] scsi host2: usb-storage 2-2:1.0
[122145.411894] scsi 2:0:0:0: Direct-Access     TOSHIBA  THNSNK512GCS8 SA 0    PQ: 0 ANSI: 6
[122145.412491] sd 2:0:0:0: Attached scsi generic sg1 type 0
[122145.413987] sd 2:0:0:0: [sdb] 1000215216 512-byte logical blocks: (512 GB/477 GiB)
[122145.413991] sd 2:0:0:0: [sdb] 4096-byte physical blocks
[122145.414231] sd 2:0:0:0: [sdb] Write Protect is off
[122145.414238] sd 2:0:0:0: [sdb] Mode Sense: 43 00 00 00
[122145.414478] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[122145.427775]  sdb: sdb1 sdb2 sdb3
[122145.429593] sd 2:0:0:0: [sdb] Attached SCSI disk

When I'm connecting a different SSD disk (GOODRAM 120 GB) using the same USB controller to both RPi4B and RPi3B+ then everything is working fine (dmesg excerpt from RPi4B):

[ 1741.975169] usb 2-1: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[ 1741.993887] usb 2-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[ 1742.011332] usb 2-1: Product: ASMT1153e
[ 1742.022665] usb 2-1: Manufacturer: asmedia
[ 1742.034215] usb 2-1: SerialNumber: 123456789299
[ 1742.048254] usb-storage 2-1:1.0: USB Mass Storage device detected
[ 1742.062837] usb-storage 2-1:1.0: Quirks match for vid 174c pid 55aa: 400000
[ 1742.077895] scsi host0: usb-storage 2-1:1.0
[ 1743.144751] scsi 0:0:0:0: Direct-Access     IR-SSDPR -S25A-120        0    PQ: 0 ANSI: 6
[ 1743.163345] sd 0:0:0:0: [sda] 234441648 512-byte logical blocks: (120 GB/112 GiB)
[ 1743.183945] sd 0:0:0:0: [sda] Write Protect is off
[ 1743.195804] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[ 1743.197731] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1743.216981]  sda: sda1 sda2
[ 1743.229365] sd 0:0:0:0: [sda] Attached SCSI disk

More information about RPi4: lsusb output:

Bus 002 Device 003: ID 174c:55aa ASMedia Technology Inc. Name: ASM1051E SATA 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge, ASM1153E SATA 6Gb/s bridge
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root 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

lsusb -v for 174c:55aa ASMedia controller:

Bus 002 Device 004: ID 174c:55aa ASMedia Technology Inc. Name: ASM1051E SATA 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge, ASM1153E SATA 6Gb/s bridge
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               3.00
  bDeviceClass            0 
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0         9
  idVendor           0x174c ASMedia Technology Inc.
  idProduct          0x55aa Name: ASM1051E SATA 6Gb/s bridge, ASM1053E SATA 6Gb/s bridge, ASM1153 SATA 3Gb/s bridge, ASM1153E SATA 6Gb/s bridge
  bcdDevice            1.00
  iManufacturer           2 asmedia
  iProduct                3 ASMT1153e
  iSerial                 1 123456789299
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x002c
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0 
    bmAttributes         0xc0
      Self Powered
    MaxPower                0mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         8 Mass Storage
      bInterfaceSubClass      6 SCSI
      bInterfaceProtocol     80 Bulk-Only
      iInterface              0 
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0400  1x 1024 bytes
        bInterval               0
        bMaxBurst              15
Binary Object Store Descriptor:
  bLength                 5
  bDescriptorType        15
  wTotalLength       0x0016
  bNumDeviceCaps          2
  USB 2.0 Extension Device Capability:
    bLength                 7
    bDescriptorType        16
    bDevCapabilityType      2
    bmAttributes   0x0000f41e
      BESL Link Power Management (LPM) Supported
    BESL value     1024 us 
    Deep BESL value    61440 us 
  SuperSpeed USB Device Capability:
    bLength                10
    bDescriptorType        16
    bDevCapabilityType      3
    bmAttributes         0x00
    wSpeedsSupported   0x000e
      Device can operate at Full Speed (12Mbps)
      Device can operate at High Speed (480Mbps)
      Device can operate at SuperSpeed (5Gbps)
    bFunctionalitySupport   1
      Lowest fully-functional device speed is Full Speed (12Mbps)
    bU1DevExitLat          10 micro seconds
    bU2DevExitLat        2047 micro seconds
can't get debug descriptor: Resource temporarily unavailable
Device Status:     0x000d
  Self Powered
  U1 Enabled
  U2 Enabled

rpi-eeprom output:

BCM2711 detected
BOOTLOADER: up-to-date
CURRENT: Tue  3 Dec 17:36:33 UTC 2019 (1575394593)
 LATEST: Tue 10 Sep 10:41:50 UTC 2019 (1568112110)
VL805: up-to-date
CURRENT: 000137ab
 LATEST: 000137ab
P33M commented 4 years ago

This is likely an upstream kernel bug fixed sometime between the 4.19 release and 5.4 release.

dwrobel commented 4 years ago

In the meantime I've tried from 5.3.11 from https://github.com/raspberrypi/linux/tree/rpi-5.3.y branch and it behaves exactly in the same way as 4.19.83.

can you build and run a 5.4 kernel on the Pi 4?

I can try 5.4.y, but is it in pair with 5.3.y? I don't see a fix for https://github.com/raspberrypi/linux/issues/3332 in 5.4.y?

P33M commented 4 years ago

The fix in that commit is specific to dwc_otg, which isn't used in host mode on Pi 4. An xhci controller provides USB host functionality. 5.4 should work well enough to replicate the test.

dwrobel commented 4 years ago

Can you run a 4.19 kernel on the x86 machine?

The oldest one I can run now on my PC is:

Linux dell 5.3.5-200.fc30.x86_64 #1 SMP Tue Oct 8 12:41:15 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

and that one is working fine:

[   80.624772] usb 2-2: new SuperSpeed Gen 1 USB device number 3 using xhci_hcd
[   80.637445] usb 2-2: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[   80.637447] usb 2-2: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[   80.637447] usb 2-2: Product: ASMT1153e
[   80.637448] usb 2-2: Manufacturer: asmedia
[   80.637449] usb 2-2: SerialNumber: 123456789299
[   80.674963] usb-storage 2-2:1.0: USB Mass Storage device detected
[   80.677759] usb-storage 2-2:1.0: Quirks match for vid 174c pid 55aa: 400000
[   80.677793] scsi host2: usb-storage 2-2:1.0
[   80.677935] usbcore: registered new interface driver usb-storage
[   80.681044] usbcore: registered new interface driver uas
[   81.726609] scsi 2:0:0:0: Direct-Access     TOSHIBA  THNSNK512GCS8 SA 0    PQ: 0 ANSI: 6
[   81.727341] scsi 2:0:0:0: Attached scsi generic sg1 type 0
[   81.728695] sd 2:0:0:0: [sdb] 1000215216 512-byte logical blocks: (512 GB/477 GiB)
[   81.728717] sd 2:0:0:0: [sdb] 4096-byte physical blocks
[   81.728947] sd 2:0:0:0: [sdb] Write Protect is off
[   81.728950] sd 2:0:0:0: [sdb] Mode Sense: 43 00 00 00
[   81.729163] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[   81.740744]  sdb: sdb1 sdb2 sdb3
[   81.741681] sd 2:0:0:0: [sdb] Attached SCSI disk

When I compiled 5.4.3 from https://github.com/raspberrypi/linux/commit/0f100bcec9fde14a71248b24eb1257b77a99970c then it's working wrongly:

First time (after boot) disk was attached:

[   92.923147] usb 2-1: new SuperSpeed Gen 1 USB device number 3 using xhci_hcd
[   92.954130] usb 2-1: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[   92.962335] usb 2-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[   92.969505] usb 2-1: Product: ASMT1153e
[   92.973362] usb 2-1: Manufacturer: asmedia
[   92.977466] usb 2-1: SerialNumber: 123456789299
[   92.984446] usb-storage 2-1:1.0: USB Mass Storage device detected
[   92.990760] usb-storage 2-1:1.0: Quirks match for vid 174c pid 55aa: 400000
[   92.997834] scsi host0: usb-storage 2-1:1.0
[   97.811757] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[   97.821124] sd 0:0:0:0: [sda] 4294902016 512-byte logical blocks: (2.20 TB/2.00 TiB)
[   97.833653] sd 0:0:0:0: [sda] Write Protect is off
[   97.838500] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[   97.839141] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  108.156126] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[  108.164408] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 00 00 00 00 08 00
[  108.179922] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[  108.197828] Buffer I/O error on dev sda, logical block 0, async page read
[  118.505593] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[  118.521495] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 00 00 00 00 08 00
[  118.536164] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[  118.551650] Buffer I/O error on dev sda, logical block 0, async page read
[  128.851320] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[  128.867790] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 00 00 00 00 00 00 08 00
[  128.882804] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[  128.898714] Buffer I/O error on dev sda, logical block 0, async page read
[  128.911671]  sda: unable to read partition table
[  128.924884] sd 0:0:0:0: [sda] Attached SCSI disk

Second time when disk was attached:

[  189.383966] usb 2-1: new SuperSpeed Gen 1 USB device number 4 using xhci_hcd
[  189.424974] usb 2-1: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[  189.442122] usb 2-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[  189.458103] usb 2-1: Product: ASMT1153e
[  189.468341] usb 2-1: Manufacturer: asmedia
[  189.478787] usb 2-1: SerialNumber: 123456789299
[  189.492533] usb-storage 2-1:1.0: USB Mass Storage device detected
[  189.505881] usb-storage 2-1:1.0: Quirks match for vid 174c pid 55aa: 400000
[  189.519218] scsi host0: usb-storage 2-1:1.0
[  194.278294] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[  194.296110] sd 0:0:0:0: [sda] 251458613520309 512-byte logical blocks: (129 PB/114 PiB)
[  194.319509] sd 0:0:0:0: [sda] Write Protect is off
[  194.330685] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[  194.332801] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

The pattern when attaching the disk for the first time: 4294902016 512-byte logical blocks: (2.20 TB/2.00 TiB) second/next time: 251458613520309 512-byte logical blocks: (129 PB/114 PiB) seems to be reproducible for all tested kernels on RPi4 (4.19.83, 5.3.11 and 5.4.3).

So, based on above it looks like it's RPi related rather than generic upstream kernel issue?

lategoodbye commented 4 years ago

Just a guess, this looks like some kind of integer overflow. Could you try the 64bit kernel for the Raspberry Pi 4?

dwrobel commented 4 years ago

Could you try the 64bit kernel for the Raspberry Pi 4?

I compiled 5.4.3 from 0f100bc for aarch64, but it also doesn't work properly.

It looks like the number of logical blocks is somehow random (excluding the aforementioned pattern when 4294902016 is being reported initially):

# uname -a
Linux rpi42-dw 5.4.3-v8+ #1 SMP PREEMPT Thu Jan 2 20:39:04 CET 2020 aarch64 aarch64 aarch64 GNU/Linux
# dmesg | grep -A 1 Direct-Access 
[  212.978403] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[  212.996341] sd 0:0:0:0: [sda] 4294902016 512-byte logical blocks: (2.20 TB/2.00 TiB)
--
[  229.049044] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[  229.071094] sd 0:0:0:0: [sda] 4294902016 512-byte logical blocks: (2.20 TB/2.00 TiB)
--
[ 1813.410867] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 1813.429233] sd 0:0:0:0: [sda] 253657938766757 512-byte logical blocks: (130 PB/115 PiB)
--
[ 2130.911673] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 2130.933896] sd 0:0:0:0: [sda] 253657636774837 512-byte logical blocks: (130 PB/115 PiB)
--
[ 2148.531874] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 2148.551408] sd 0:0:0:0: [sda] 251458613520293 512-byte logical blocks: (129 PB/114 PiB)
--
[ 2172.509568] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 2172.531474] sd 0:0:0:0: [sda] 251458546410421 512-byte logical blocks: (129 PB/114 PiB)
--
[ 2197.499664] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 2197.518905] sd 0:0:0:0: [sda] 253657603222453 512-byte logical blocks: (130 PB/115 PiB)
--
[45716.436432] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[45716.456954] sd 0:0:0:0: [sda] 251458647075749 512-byte logical blocks: (129 PB/114 PiB)
--
[45732.954080] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[45732.970424] sd 0:0:0:0: [sda] 254757148403509 512-byte logical blocks: (130 PB/116 PiB)
--
[45773.059764] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[45773.078669] sd 0:0:0:0: [sda] 251458579966757 512-byte logical blocks: (129 PB/114 PiB)
--
[46094.259233] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[46094.280995] sd 0:0:0:0: [sda] 251458579966885 512-byte logical blocks: (129 PB/114 PiB)
dwrobel commented 4 years ago

Just a guess, this looks like some kind of integer overflow.

I also got access to the quite old PC laptop powered by 32-bit i686 PAE kernel:

Linux compaq 4.18.19-100.fc27.i686+PAE #1 SMP Wed Nov 14 22:19:17 UTC 2018 i686 i686 i386 GNU/Linux

and when attaching a disk it works as expected (proper capacity is reported). So, I assume that could give us a hint that the code could run also fine on the 32-bit kernel version without an issue.

lategoodbye commented 4 years ago

I think these buffer I/O errors are related to this issue. Could you please confirm, that these buffer I/O errors only appear on the platforms which reports the wrong capacity? Please name the full product name of the SSD disk and the SATA-USB-bridge. Just another guess, what's the output of cat /proc/cpu/alignment on the Raspberry Pi 4 with 32 bit kernel?

dwrobel commented 4 years ago

I think these buffer I/O errors are related to this issue.

IMHO those are related to wrongly reported capacity of the disk.

Could you please confirm, that these buffer I/O errors only appear on the platforms which reports the wrong capacity? Please name the full product name of the SSD disk and the SATA-USB-bridge.

Yes, the I/O errors appears only on the RPI(s) on PC there are no errors.

174c:55aa ASMedia controller [122145.411894] scsi 2:0:0:0: Direct-Access TOSHIBA THNSNK512GCS8 SA 0 PQ: 0 ANSI: 6

Please have a look at the initial log from my PC https://github.com/raspberrypi/linux/issues/3388#issue-544543983 for complete log from the 5.4.5 kernel and more details from lsusb for 174c:55aa.

Just another guess, what's the output of cat /proc/cpu/alignment on the Raspberry Pi 4 with 32 bit kernel?

$ uname -a
Linux rpi42-dw 5.4.3-1.rpi4.fc31.armv7hl #1 SMP Thu Jan 2 14:21:33 CET 2020 armv7l armv7l armv7l GNU/Linux
$ cat /proc/cpu/alignment
User:       0
System:     0 (0x0)
Skipped:    0
Half:       0
Word:       0
DWord:      0
Multi:      0
User faults:    2 (fixup)
dwrobel commented 4 years ago

I see in the wireshark dump that the value from dmesg line (when attaching a disk for the first time):

4294902016 512-byte logical blocks: (2.20 TB/2.00 TiB)

appears in the USB packet (in the form off-by-one):

Logical Block Address: 4294902015 (2047 GB)

wireshark packet (101) dump:

No.     Time           Source                Destination           Protocol Length Info
    101 15.406140      2.6.1                 host                  USBMS    96     SCSI: Data In LUN: 0x00 (Service Action In(16) Response Data) 

Frame 101: 96 bytes on wire (768 bits), 96 bytes captured (768 bits) on interface 0
    Interface id: 0 (-)
        Interface name: -
    Encapsulation type: USB packets with Linux header and padding (115)
    Arrival Time: Jan  2, 2020 17:55:28.558053000 CET
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1577984128.558053000 seconds
    [Time delta from previous captured frame: 0.000075000 seconds]
    [Time delta from previous displayed frame: 0.000075000 seconds]
    [Time since reference or first frame: 15.406140000 seconds]
    Frame Number: 101
    Frame Length: 96 bytes (768 bits)
    Capture Length: 96 bytes (768 bits)
    [Frame is marked: True]
    [Frame is ignored: False]
    [Protocols in frame: usb:usbms]
USB URB
    [Source: 2.6.1]
    [Destination: host]
    URB id: 0x00000000e4116300
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_BULK (0x03)
    Endpoint: 0x81, Direction: IN
    Device: 6
    URB bus id: 2
    Device setup request: not relevant ('-')
    Data: present (0)
    URB sec: 1577984128
    URB usec: 558053
    URB status: Success (0)
    URB length [bytes]: 32
    Data length [bytes]: 32
    [Request in: 100]
    [Time from request: 0.000075000 seconds]
    [bInterfaceClass: Mass Storage (0x08)]
    Unused Setup Header
    Interval: 0
    Start frame: 0
    Copy of Transfer Flags: 0x00000201, Short not OK, Dir IN
    Number of ISO descriptors: 0
USB Mass Storage
SCSI Payload (Service Action In(16) Response Data)
    [LUN: 0x0000]
    [Command Set:Direct Access Device (0x00) ]
    [SBC Opcode: Service Action In(16) (0x9e)]
    [Request in: 98]
    [Response in: 103]
    Logical Block Address: 4294902015 (2047 GB)
    Block size in bytes: 512
    .... ...0 = PROT_EN: False
    0000 .... = P_I_EXPONENT: 0
    .... 0000 = LOGICAL_BLOCKS_PER_PHYSICAL_BLOCK_EXPONENT: 0
    0... .... = LBPME (logical block provisioning management enabled) / TPE: False
    .0.. .... = LBPRZ (logical block provisioning read zeros) / TPRZ: False
    ..00 0000 0000 0000 = LOWEST_ALIGNED_LBA: 0

Converting:

Logical Block Address: 4294902015 (2047 GB)

into hex:

$ python3 -c 'print (hex(4294902015))'
0xffff00ff

doesn't look like the value is fully random.

dwrobel commented 4 years ago

I think these buffer I/O errors are related to this issue.

IMHO those are related to wrongly reported capacity of the disk.

Or those errors cause the capacity to be wrongly reported.

Here is the prove that reading from the drive on PC do not produce any I/O errors:

$ uname -a
Linux dell 5.4.5-300.fc31.x86_64 #1 SMP Thu Dec 19 19:37:41 UTC 2019 x86_64 x86_64 x86_64 
GNU/Linux
$ dmesg | tail -n 18
[75391.093194] usb 2-2: new SuperSpeed Gen 1 USB device number 6 using xhci_hcd
[75391.106236] usb 2-2: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[75391.106240] usb 2-2: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[75391.106242] usb 2-2: Product: ASMT1153e
[75391.106245] usb 2-2: Manufacturer: asmedia
[75391.106247] usb 2-2: SerialNumber: 123456789299
[75391.107880] usb-storage 2-2:1.0: USB Mass Storage device detected
[75391.109806] usb-storage 2-2:1.0: Quirks match for vid 174c pid 55aa: 400000
[75391.109878] scsi host2: usb-storage 2-2:1.0
[75392.168803] scsi 2:0:0:0: Direct-Access     TOSHIBA  THNSNK512GCS8 SA 0    PQ: 0 ANSI: 6
[75392.169300] sd 2:0:0:0: Attached scsi generic sg1 type 0
[75392.170320] sd 2:0:0:0: [sdb] 1000215216 512-byte logical blocks: (512 GB/477 GiB)
[75392.170324] sd 2:0:0:0: [sdb] 4096-byte physical blocks
[75392.170566] sd 2:0:0:0: [sdb] Write Protect is off
[75392.170569] sd 2:0:0:0: [sdb] Mode Sense: 43 00 00 00
[75392.170788] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[75392.185470]  sdb: sdb1 sdb2 sdb3
[75392.186263] sd 2:0:0:0: [sdb] Attached SCSI disk
$ sudo dd if=/dev/sdb of=sdb bs=1M count=1024
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 0.702133 s, 1.5 GB/s
$ hexdump -C sdb | head -n 30
00000000  fa b8 00 10 8e d0 bc 00  b0 b8 00 00 8e d8 8e c0  |................|
00000010  fb be 00 7c bf 00 06 b9  00 02 f3 a4 ea 21 06 00  |...|.........!..|
00000020  00 be be 07 38 04 75 0b  83 c6 10 81 fe fe 07 75  |....8.u........u|
00000030  f3 eb 16 b4 02 b0 01 bb  00 7c b2 80 8a 74 01 8b  |.........|...t..|
00000040  4c 02 cd 13 ea 00 7c 00  00 eb fe 00 00 00 00 00  |L.....|.........|
00000050  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
000001b0  00 00 00 00 00 00 00 00  bc 06 4f a4 00 00 00 04  |..........O.....|
000001c0  01 04 0c 34 42 35 00 08  00 00 00 60 02 00 80 35  |...4B5.....`...5|
000001d0  41 35 83 fe c2 ff 00 68  02 00 00 48 0f 00 00 fe  |A5.....h...H....|
000001e0  c2 ff 83 fe c2 ff 00 b0  11 00 00 80 4a 00 00 00  |............J...|
000001f0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 55 aa  |..............U.|
00000200  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
00100000  eb 3c 90 6d 6b 66 73 2e  66 61 74 00 02 04 04 00  |.<.mkfs.fat.....|
00100010  02 00 02 00 00 f8 98 00  20 00 40 00 00 00 00 00  |........ .@.....|
00100020  00 60 02 00 80 00 29 28  f1 e3 6d 4e 4f 20 4e 41  |.`....)(..mNO NA|
00100030  4d 45 20 20 20 20 46 41  54 31 36 20 20 20 0e 1f  |ME    FAT16   ..|
00100040  be 5b 7c ac 22 c0 74 0b  56 b4 0e bb 07 00 cd 10  |.[|.".t.V.......|
00100050  5e eb f0 32 e4 cd 16 cd  19 eb fe 54 68 69 73 20  |^..2.......This |
00100060  69 73 20 6e 6f 74 20 61  20 62 6f 6f 74 61 62 6c  |is not a bootabl|
00100070  65 20 64 69 73 6b 2e 20  20 50 6c 65 61 73 65 20  |e disk.  Please |
00100080  69 6e 73 65 72 74 20 61  20 62 6f 6f 74 61 62 6c  |insert a bootabl|
00100090  65 20 66 6c 6f 70 70 79  20 61 6e 64 0d 0a 70 72  |e floppy and..pr|
001000a0  65 73 73 20 61 6e 79 20  6b 65 79 20 74 6f 20 74  |ess any key to t|
001000b0  72 79 20 61 67 61 69 6e  20 2e 2e 2e 20 0d 0a 00  |ry again ... ...|
001000c0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
001001f0  00 00 00 00 00 00 00 00  00 00 00 00 00 00 55 aa  |..............U.|
00100200  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|

The same doesn't work at all on the RPI4:

$ uname -a
Linux rpi42-dw 5.4.3-1.rpi4.fc31.armv7hl #1 SMP Thu Jan 2 14:21:33 CET 2020 armv7l armv7l armv7l GNU/Linux
$ dmesg | tail -n 18
[ 1841.578976] usb 2-1: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 1841.620011] usb 2-1: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[ 1841.635755] usb 2-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[ 1841.650471] usb 2-1: Product: ASMT1153e
[ 1841.659972] usb 2-1: Manufacturer: asmedia
[ 1841.669760] usb 2-1: SerialNumber: 123456789299
[ 1841.682418] usb-storage 2-1:1.0: USB Mass Storage device detected
[ 1841.695529] usb-storage 2-1:1.0: Quirks match for vid 174c pid 55aa: 400000
[ 1841.708420] scsi host0: usb-storage 2-1:1.0
[ 1846.530348] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 1846.547738] sd 0:0:0:0: [sda] 251458613520309 512-byte logical blocks: (129 PB/114 PiB)
[ 1846.564219] sd 0:0:0:0: [sda] Write Protect is off
[ 1846.575211] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[ 1846.576070] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1856.954271] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1856.970238] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[ 1856.987105] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 1857.002549] Buffer I/O error on dev sda, logical block 0, async page read
$ sudo dd if=/dev/sda of=sdb bs=1M count=1024

dd got stuck and after a while looking at dmesg on another terminal I see:

$ dmesg | tail -n 93
[ 1841.578976] usb 2-1: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 1841.620011] usb 2-1: New USB device found, idVendor=174c, idProduct=55aa, bcdDevice= 1.00
[ 1841.635755] usb 2-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[ 1841.650471] usb 2-1: Product: ASMT1153e
[ 1841.659972] usb 2-1: Manufacturer: asmedia
[ 1841.669760] usb 2-1: SerialNumber: 123456789299
[ 1841.682418] usb-storage 2-1:1.0: USB Mass Storage device detected
[ 1841.695529] usb-storage 2-1:1.0: Quirks match for vid 174c pid 55aa: 400000
[ 1841.708420] scsi host0: usb-storage 2-1:1.0
[ 1846.530348] scsi 0:0:0:0: Direct-Access                    SATM1135 e 0    PQ: 0 ANSI: 6
[ 1846.547738] sd 0:0:0:0: [sda] 251458613520309 512-byte logical blocks: (129 PB/114 PiB)
[ 1846.564219] sd 0:0:0:0: [sda] Write Protect is off
[ 1846.575211] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
[ 1846.576070] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1856.954271] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1856.970238] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[ 1856.987105] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 1857.002549] Buffer I/O error on dev sda, logical block 0, async page read
[ 1867.378589] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1867.394989] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 01 00 00 00 07 00 00
[ 1867.411550] blk_update_request: I/O error, dev sda, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
[ 1867.427546] Buffer I/O error on dev sda, logical block 1, async page read
[ 1867.440630] Buffer I/O error on dev sda, logical block 2, async page read
[ 1867.453654] Buffer I/O error on dev sda, logical block 3, async page read
[ 1867.466583] Buffer I/O error on dev sda, logical block 4, async page read
[ 1867.479516] Buffer I/O error on dev sda, logical block 5, async page read
[ 1867.492335] Buffer I/O error on dev sda, logical block 6, async page read
[ 1867.505021] Buffer I/O error on dev sda, logical block 7, async page read
[ 1877.812191] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1877.828360] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[ 1877.845530] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 1877.861099] Buffer I/O error on dev sda, logical block 0, async page read
[ 1888.218132] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1888.234221] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 01 00 00 00 07 00 00
[ 1888.249549] blk_update_request: I/O error, dev sda, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
[ 1888.265109] Buffer I/O error on dev sda, logical block 1, async page read
[ 1888.277615] Buffer I/O error on dev sda, logical block 2, async page read
[ 1888.290126] Buffer I/O error on dev sda, logical block 3, async page read
[ 1888.302582] Buffer I/O error on dev sda, logical block 4, async page read
[ 1888.315096] Buffer I/O error on dev sda, logical block 5, async page read
[ 1888.327610] Buffer I/O error on dev sda, logical block 6, async page read
[ 1888.340119] Buffer I/O error on dev sda, logical block 7, async page read
[ 1898.626422] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1898.642581] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[ 1898.659848] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 1898.675593] Buffer I/O error on dev sda, logical block 0, async page read
[ 1909.033666] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1909.050177] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 01 00 00 00 07 00 00
[ 1909.066706] blk_update_request: I/O error, dev sda, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
[ 1909.082676] Buffer I/O error on dev sda, logical block 1, async page read
[ 1909.095667] Buffer I/O error on dev sda, logical block 2, async page read
[ 1909.108568] Buffer I/O error on dev sda, logical block 3, async page read
[ 1909.121345] Buffer I/O error on dev sda, logical block 4, async page read
[ 1909.134053] Buffer I/O error on dev sda, logical block 5, async page read
[ 1909.146763] Buffer I/O error on dev sda, logical block 6, async page read
[ 1909.159379] Buffer I/O error on dev sda, logical block 7, async page read
[ 1909.171979]  sda: unable to read partition table
[ 1909.184634] sd 0:0:0:0: [sda] Attached SCSI disk
[ 1912.502717] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1912.518678] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 20 00 00
[ 1912.535484] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x80700 phys_seg 4 prio class 0
[ 1922.955327] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1922.971187] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[ 1922.988056] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 1923.003631] Buffer I/O error on dev sda, logical block 0, async page read
[ 1933.363419] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 1933.379761] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 01 00 00 00 07 00 00
[ 1933.396268] blk_update_request: I/O error, dev sda, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
[ 1933.412128] Buffer I/O error on dev sda, logical block 1, async page read
[ 1933.425016] Buffer I/O error on dev sda, logical block 2, async page read
[ 1933.437750] Buffer I/O error on dev sda, logical block 3, async page read
[ 1933.450393] Buffer I/O error on dev sda, logical block 4, async page read
[ 1933.463012] Buffer I/O error on dev sda, logical block 5, async page read
[ 1933.475526] Buffer I/O error on dev sda, logical block 6, async page read
[ 1933.487892] Buffer I/O error on dev sda, logical block 7, async page read
[ 1937.609826] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 2105.484065] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 2105.499802] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 08 00 00 00
[ 2105.516455] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x80700 phys_seg 128 prio class 0
[ 2115.961557] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 2115.977433] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 00 00 00 00 01 00 00
[ 2115.994204] blk_update_request: I/O error, dev sda, sector 0 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 2116.009530] Buffer I/O error on dev sda, logical block 0, async page read
[ 2126.393176] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x07 driverbyte=0x00
[ 2126.409313] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 00 00 00 01 00 00 00 07 00 00
[ 2126.426006] blk_update_request: I/O error, dev sda, sector 1 op 0x0:(READ) flags 0x0 phys_seg 7 prio class 0
[ 2126.441843] Buffer I/O error on dev sda, logical block 1, async page read
[ 2126.454749] Buffer I/O error on dev sda, logical block 2, async page read
[ 2126.467626] Buffer I/O error on dev sda, logical block 3, async page read
[ 2126.480452] Buffer I/O error on dev sda, logical block 4, async page read
[ 2126.493164] Buffer I/O error on dev sda, logical block 5, async page read
[ 2126.505722] Buffer I/O error on dev sda, logical block 6, async page read
[ 2126.518107] Buffer I/O error on dev sda, logical block 7, async page read

Long story short the "TOSHIBA THNSNK512GCS8 SA" is the original disk from my Laptop which I used for last two years without any single issue. As the space run out I bought a new 1TB disk for my PC and had plans to use the "TOSHIBA THNSNK512GCS8 SA" with one of my RPi4(s).

On the other hand, on the RPi4, I used the controller "ASMT1153e" with the "IR-SSDPR -S25A-120" disk as a root filesystem for a few months. That machine constantly runs openhab/graphana/influxdb and was used for building many packages using mock() for other RPi(s) without any single issue.

So I have quite well tested:

Now it appears that on the RPi4 (and so far only on that platform) the combination: "ASMT1153e" controller + "TOSHIBA THNSNK512GCS8 SA" disk - simply doesn't work at all.

Based on above I'm rather reluctant to blame either "ASMT1153e" controller or "TOSHIBA THNSNK512GCS8 SA" disk.

tfachmann commented 3 years ago

I experience a similar behavior you have posted in your last comment. I was blaming my controller / adapter which I then replaced but the error persists. It is incredibly frustrating. Anyway, it isn't something I would expect from the disk but for me it is basically the only remaining thing I haven't swapped out.

Did you finally come to a conclusion what has caused the errors and you could you fix it @dwrobel?