OS: Raspberry Pi OS on 5.10.52-v7l+ kernel, with 03/09/2020 eeprom
Symptom: USB attached hard disk error, after reboot, disk is damaged and cannot be read. 3TB disk can only be recognized as a 3.7GB device with IO error.
Goal: Identify the device at fault and prevent future loss.
I have used my raspberry pi as NAS device for almost two years, but recently its USB attached hard drive stopped working.
The disk error seemed to have appeared at 9 am, with both partitions unmounted and unable to be remounted.
When I realized the disk error at 4 pm and tried to reboot, the USB external disk cannot be mounted via fstab during reboot. And I had to modify cmdline.txt to reset fstab in rescue mode. After that, the disk reports Input/Output error on any command, fdisk, lsblk whatever.
I wanted to figure out if it was an eeprom issue as with https://www.raspberrypi.org/forums/viewtopic.php?t=307854, or an issue with my ORICO USB hard drive hub.
The relevant syslog is as follows,
Aug 26 09:12:55 dottypi kernel: [808772.369054] sd 0:0:0:0: [sda] tag#1 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x08 cmd_age=12s
Aug 26 09:12:55 dottypi kernel: [808772.369096] sd 0:0:0:0: [sda] tag#1 Sense Key : 0x3 [current]
Aug 26 09:12:55 dottypi kernel: [808772.369132] sd 0:0:0:0: [sda] tag#1 ASC=0x11 ASCQ=0x0
Aug 26 09:12:55 dottypi kernel: [808772.369163] sd 0:0:0:0: [sda] tag#1 CDB: opcode=0x88 88 00 00 00 00 00 9d 76 33 e8 00 00 00 28 00 00
Aug 26 09:12:55 dottypi kernel: [808772.369195] blk_update_request: critical medium error, dev sda, sector 2641769448 op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0
Aug 26 09:13:19 dottypi kernel: [808797.156003] sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x08 cmd_age=24s
Aug 26 09:13:19 dottypi kernel: [808797.156050] sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current]
Aug 26 09:13:19 dottypi kernel: [808797.156078] sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0
Aug 26 09:13:19 dottypi kernel: [808797.156107] sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x88 88 00 00 00 00 00 9d 76 33 e8 00 00 00 08 00 00
Aug 26 09:13:19 dottypi kernel: [808797.156139] blk_update_request: critical medium error, dev sda, sector 2641769448 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
Aug 26 09:18:23 dottypi kernel: [809100.323200] sd 0:0:0:0: [sda] tag#6 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=0x08 cmd_age=10s
Aug 26 09:18:23 dottypi kernel: [809100.323250] sd 0:0:0:0: [sda] tag#6 Sense Key : 0x7 [current]
Aug 26 09:18:23 dottypi kernel: [809100.323278] sd 0:0:0:0: [sda] tag#6 ASC=0x27 ASCQ=0x0
Aug 26 09:18:23 dottypi kernel: [809100.323308] sd 0:0:0:0: [sda] tag#6 CDB: opcode=0x88 88 00 00 00 00 00 9e 7f 5c 08 00 00 00 28 00 00
Aug 26 09:18:23 dottypi kernel: [809100.323340] blk_update_request: critical target error, dev sda, sector 2659146760 op 0x0:(READ) flags 0x80700 phys_seg 5 prio class 0
Aug 26 09:18:53 dottypi kernel: [809130.469818] sd 0:0:0:0: [sda] tag#4 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD IN
Aug 26 09:18:53 dottypi kernel: [809130.469841] sd 0:0:0:0: [sda] tag#4 CDB: opcode=0x88 88 00 00 00 00 00 9e 7f 5c 08 00 00 00 08 00 00
Aug 26 09:18:53 dottypi kernel: [809130.509834] scsi host0: uas_eh_device_reset_handler start
Aug 26 09:18:53 dottypi kernel: [809130.660965] usb 2-2: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd
Aug 26 09:18:53 dottypi kernel: [809130.696317] scsi host0: uas_eh_device_reset_handler success
Aug 26 09:19:28 dottypi kernel: [809165.669971] sd 0:0:0:0: [sda] tag#5 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD OUT
Aug 26 09:19:28 dottypi kernel: [809165.669993] sd 0:0:0:0: [sda] tag#5 CDB: opcode=0x8a 8a 08 00 00 00 00 e0 c2 ab 36 00 00 00 02 00 00
Aug 26 09:19:28 dottypi kernel: [809165.670222] xhci_hcd 0000:01:00.0: WARNING: Host System Error
Aug 26 09:19:33 dottypi kernel: [809170.689977] xhci_hcd 0000:01:00.0: xHCI host not responding to stop endpoint command.
Aug 26 09:19:33 dottypi kernel: [809170.689994] xhci_hcd 0000:01:00.0: USBSTS: HCHalted HSE EINT
Aug 26 09:19:33 dottypi kernel: [809170.690038] xhci_hcd 0000:01:00.0: xHCI host controller not responding, assume dead
Aug 26 09:19:33 dottypi kernel: [809170.690081] xhci_hcd 0000:01:00.0: HC died; cleaning up
Aug 26 09:19:33 dottypi kernel: [809170.690742] usb 1-1: USB disconnect, device number 2
Aug 26 09:19:33 dottypi kernel: [809170.691922] usb 2-2: USB disconnect, device number 2
Aug 26 09:19:33 dottypi kernel: [809170.692504] sd 0:0:0:0: [sda] tag#6 uas_zap_pending 0 uas-tag 2 inflight: CMD
Aug 26 09:19:33 dottypi kernel: [809170.692523] sd 0:0:0:0: [sda] tag#6 CDB: opcode=0x88 88 00 00 00 00 00 9e 7f 5c 08 00 00 00 08 00 00
Aug 26 09:19:33 dottypi kernel: [809170.730039] sd 0:0:0:0: Device offlined - not ready after error recovery
Aug 26 09:19:33 dottypi kernel: [809170.730059] sd 0:0:0:0: Device offlined - not ready after error recovery
Aug 26 09:19:33 dottypi kernel: [809170.769999] blk_update_request: I/O error, dev sda, sector 2659146760 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
Aug 26 09:19:33 dottypi kernel: [809170.770042] blk_update_request: I/O error, dev sda, sector 3770854198 op 0x1:(WRITE) flags 0x29800 phys_seg 1 prio class 0
Aug 26 09:19:33 dottypi kernel: [809170.770062] blk_update_request: I/O error, dev sda, sector 3770854198 op 0x1:(WRITE) flags 0x29800 phys_seg 1 prio class 0
Aug 26 09:19:33 dottypi kernel: [809170.770084] XFS (sda2): log I/O error -5
Aug 26 09:19:33 dottypi kernel: [809170.770166] XFS (sda2): xfs_do_force_shutdown(0x2) called from line 1196 of file fs/xfs/xfs_log.c. Return address = 23be8862
Aug 26 09:19:33 dottypi kernel: [809170.770181] XFS (sda2): Log I/O Error Detected. Shutting down filesystem
Aug 26 09:19:33 dottypi kernel: [809170.770208] XFS (sda2): Please unmount the filesystem and rectify the problem(s)
Aug 26 09:19:34 dottypi kernel: [809171.347113] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Aug 26 09:19:34 dottypi systemd[1]: Stopped target Local File Systems.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Documents...
Aug 26 09:19:34 dottypi kernel: [809171.534981] XFS (sda1): Unmounting Filesystem
Aug 26 09:19:34 dottypi kernel: [809171.535137] XFS (sda1): log I/O error -5
Aug 26 09:19:34 dottypi kernel: [809171.535181] XFS (sda1): xfs_do_force_shutdown(0x2) called from line 1196 of file fs/xfs/xfs_log.c. Return address = 23be8862
Aug 26 09:19:34 dottypi kernel: [809171.535188] XFS (sda1): Log I/O Error Detected. Shutting down filesystem
Aug 26 09:19:34 dottypi kernel: [809171.535201] XFS (sda1): Please unmount the filesystem and rectify the problem(s)
Aug 26 09:19:34 dottypi kernel: [809171.535232] XFS (sda1): Unable to update superblock counters. Freespace may not be correct on next mount.
Aug 26 09:19:34 dottypi umount[10749]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Documents.mount: Succeeded.
Aug 26 09:19:34 dottypi systemd[1]: Unmounted /mnt/Documents.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10751]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10752]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10753]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10754]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10755]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10756]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10757]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10758]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10759]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10760]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10761]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10762]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10763]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10764]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10765]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device. Stopping, too.
Aug 26 09:19:34 dottypi systemd[1]: Unmounting /mnt/Videos...
Aug 26 09:19:34 dottypi umount[10766]: umount: /mnt/Videos: target is busy.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Mount process exited, code=exited, status=32/n/a
Aug 26 09:19:34 dottypi systemd[1]: Failed unmounting /mnt/Videos.
Aug 26 09:19:34 dottypi systemd[1]: mnt-Videos.mount: Unit is bound to inactive unit dev-disk-by\x2dpartuuid-d6d003c5\x2dce0f\x2d4af1\x2da18b\x2dd82175e41a10.device, but not stopping since we tried this too often recently.
Aug 26 09:19:34 dottypi kernel: [809171.940001] sd 0:0:0:0: [sda] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=0x00
Aug 26 09:19:34 dottypi kernel: [809172.000572] xhci_hcd 0000:01:00.0: WARN Can't disable streams for endpoint 0x82, streams are being disabled already
