[RPi5] USB SSD drive unmounting after a while

Clipps · December 18, 2023 at 4:15 AM

I seem to have an issue (seems to be consistent across several nightlies now) that after a while, the SSD which is connected via USB 3.0 unmounts, prompting a restart of the Pi 5. It doesn't seem to happen when watching content so must be some kind of low power state the Pi 5 enters when idle. I can interact with Libreelec but none of my files are present and I can't ssh into the Pi; I'm assuming all I'm interacting with here is what is loaded into RAM.

I'm using the official 27 watt power plug, and never had this issue when using a Pi 4 (with the standard Pi 4 plug) so it must be some new, lower power usage features unmounting the SSD. Or maybe something to do with HDMI CEC when the TV is turned off.

Any ideas? Thank you

ghtester · December 27, 2023 at 2:11 AM

Try to connect through SSH before the issue happen. Then let the box to fell into idle state and you should be still able to display the kernel log with dmesg command to see what happened.

**chewitt** · December 27, 2023 at 5:19 AM

If the device is booted from USB? and then the device unmounts the OS will mark things read-only and a bunch of things will stop working. Run "journalctl -f" and you might get lucky and see somehing in the journal before things start to fail. If you're unable to SSH in then it's likely the connection drops so you won't be able to run dmesg.

ghtester · December 27, 2023 at 9:58 AM

My experience is (using USB to SATA & SATA HDD to boot & run LE) like described in my previous post. If the boot device is unmounted and there's SSH connection already, it's not dropped and some commands (including dmesg) still works.

But of course it's not able to make a new SSH connection anymore (even if the boot device is remounted).

genisho · December 27, 2023 at 11:22 AM

hi

i have expirience so much the same when the external disk (USB) not mounted & not recognize by the OS after upgrading to 11.xx .

i even tried to upgrade to 12.00 but it didnt help, the issue reamins.

what solve the problem for me is downgrade the OS to 10.

Clipps · January 3, 2024 at 9:10 AM

Apologies for the late reply... been busy with the festive period.

Thank you very much for the replies. I've been updating to the latest nightly every time a new one has released and the issue persists. The issue with having a constant ssh connection is the issue is very sporadic. Sometimes the uptime will be a day or two, other times it'll be a few hours; it's very inconsistent.

Is there a more permanent log file which I can look at which persists between reboots?

genisho It doesn't look like OS 10 is an option for me since i'm using the RPi 5 here but I might go so far as to try a version 11 nightly and see if the issue persists there.

Clipps · January 3, 2024 at 9:32 AM

Actually, by chance i think I managed to catch the errors with those logging commands

Code

[  590.233378] usb 4-1: cmd cmplt err -71 
[  595.459902] scsi host0: uas_pre_reset: timed out 
[  595.460150] sd 0:0:0:0: [sda] tag#16 uas_zap_pending 0 uas-tag 1 inflight: CMD  
[  595.460154] sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x28 28 00 00 01 06 51 00 00 20 00 
[  595.460166] sd 0:0:0:0: [sda] tag#16 UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=DRIVER_OK cmd_age=5s 
[  595.460174] sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x28 28 00 00 01 06 51 00 00 20 00 
[  595.460177] I/O error, dev sda, sector 67153 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2 
[  595.460216] device offline error, dev sda, sector 67153 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2 
[  595.460230] I/O error, dev loop0, sector 36118 op 0x0:(READ) flags 0x800 phys_seg 2 prio class 2 
[  595.460242] SQUASHFS error: Failed to read block 0x11a2cbc: -5 
[  595.460245] SQUASHFS error: Unable to read fragment cache entry [11a2cbc] 
[  595.460288] SQUASHFS error: Unable to read fragment cache entry [11a2cbc] 
[  595.460290] SQUASHFS error: Unable to read page, block 11a2cbc, size 3563 
[  595.460608] SQUASHFS error: Unable to read fragment cache entry [11a2cbc] 
[  595.460611] SQUASHFS error: Unable to read page, block 11a2cbc, size 3563 
[  595.463291] device offline error, dev sda, sector 0 op 0x1:(WRITE) flags 0x800 phys_seg 0 prio class 2 
[  595.464815] EXT4-fs (sda2): shut down requested (2) 
[  595.464826] Aborting journal on device sda2-8. 
[  595.464877] device offline error, dev sda, sector 1089538 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 2 
[  595.464895] device offline error, dev sda, sector 1089538 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 2 
[  595.464900] Buffer I/O error on dev sda2, logical block 16385, lost sync page write 
[  595.464925] JBD2: I/O error when updating journal superblock for sda2-8. 
[  595.523274] sd 0:0:0:0: [sda] Synchronizing SCSI cache 
[  595.723261] sd 0:0:0:0: [sda] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=DRIVER_OK 
[  595.723557] usb 4-1: Disable of device-initiated U1 failed. 
[  595.723577] usb 4-1: Disable of device-initiated U2 failed. 
[  595.724199] usb 4-1: Enable of device-initiated U1 failed. 
[  595.724328] usb 4-1: Enable of device-initiated U2 failed. 
[  595.920077] usb 4-1: reset SuperSpeed USB device number 2 using xhci-hcd 
[  595.940335] scsi host1: uas 
[  595.941286] scsi 1:0:0:0: Direct-Access     JMicron  Tech             0214 PQ: 0 ANSI: 6 
[  595.944453] sd 1:0:0:0: [sdb] 937703088 512-byte logical blocks: (480 GB/447 GiB) 
[  595.944460] sd 1:0:0:0: [sdb] 4096-byte physical blocks 
[  595.945170] sd 1:0:0:0: [sdb] Write Protect is off 
[  595.945175] sd 1:0:0:0: [sdb] Mode Sense: 53 00 00 08 
[  595.945554] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 
[  595.945775] sd 1:0:0:0: [sdb] Preferred minimum I/O size 4096 bytes 
[  595.945778] sd 1:0:0:0: [sdb] Optimal transfer size 33553920 bytes not a multiple of preferred minimum block size (4096 bytes) 
[  596.440014]  sdb: sdb1 sdb2 
[  596.440578] sd 1:0:0:0: [sdb] Attached SCSI disk 
[  596.617309] EXT4-fs (sdb2): recovery complete 
[  596.618333] EXT4-fs (sdb2): mounted filesystem 69675956-de9a-48ac-b10c-13fcd7f42e78 r/w with ordered data mode. Quota mode: disabled.

Display More

Code

LibreELEC (community): nightly-20231231-dfd843f (RPi5.aarch64) 
LibreELEC:~ # journalctl -f 
Jan 03 09:14:40 LibreELEC systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 
Jan 03 09:14:40 LibreELEC systemd[1]: Finished systemd-update-utmp-runlevel.service. 
Jan 03 09:14:40 LibreELEC systemd[1]: Started kodi.service. 
Jan 03 09:14:40 LibreELEC systemd[1]: Reached target kodi.target. 
Jan 03 09:14:40 LibreELEC systemd[1]: Startup finished in 1.971s (kernel) + 5.817s (userspace) = 7.789s. 
Jan 03 09:14:40 LibreELEC (kodi.sh)[831]: kodi.service: Referenced but unset environment variable evaluates to an empty string: KODI_DEBUG 
Jan 03 09:14:41 LibreELEC kernel: kodi.bin[835]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set 
Jan 03 09:15:07 LibreELEC systemd[1]: systemd-hostnamed.service: Deactivated successfully. 
Jan 03 09:15:16 LibreELEC sshd[899]: Accepted password for root from 192.168.50.87 port 50225 ssh2 
Jan 03 09:17:21 LibreELEC sshd[926]: Accepted password for root from 192.168.50.87 port 50228 ssh2 
Jan 03 09:24:23 LibreELEC kernel: usb 4-1: cmd cmplt err -71 
Jan 03 09:24:28 LibreELEC kernel: scsi host0: uas_pre_reset: timed out 
Jan 03 09:24:28 LibreELEC kernel: sd 0:0:0:0: [sda] tag#16 uas_zap_pending 0 uas-tag 1 inflight: CMD  
Jan 03 09:24:28 LibreELEC kernel: sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x28 28 00 00 01 06 51 00 00 20 00 
Jan 03 09:24:28 LibreELEC kernel: sd 0:0:0:0: [sda] tag#16 UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=DRIVER_OK cmd_age=5s 
Jan 03 09:24:28 LibreELEC kernel: sd 0:0:0:0: [sda] tag#16 CDB: opcode=0x28 28 00 00 01 06 51 00 00 20 00 
Jan 03 09:24:28 LibreELEC kernel: I/O error, dev sda, sector 67153 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2 
Jan 03 09:24:28 LibreELEC kernel: device offline error, dev sda, sector 67153 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2 
Jan 03 09:24:28 LibreELEC kernel: I/O error, dev loop0, sector 36118 op 0x0:(READ) flags 0x800 phys_seg 2 prio class 2 
Jan 03 09:24:28 LibreELEC kernel: SQUASHFS error: Failed to read block 0x11a2cbc: -5 
Jan 03 09:24:28 LibreELEC kernel: SQUASHFS error: Unable to read fragment cache entry [11a2cbc] 
Jan 03 09:24:28 LibreELEC kernel: SQUASHFS error: Unable to read fragment cache entry [11a2cbc] 
Jan 03 09:24:28 LibreELEC kernel: SQUASHFS error: Unable to read page, block 11a2cbc, size 3563 
Jan 03 09:24:28 LibreELEC kernel: SQUASHFS error: Unable to read fragment cache entry [11a2cbc] 
Jan 03 09:24:28 LibreELEC kernel: SQUASHFS error: Unable to read page, block 11a2cbc, size 3563 
Jan 03 09:24:28 LibreELEC smbd[1149]: [2024/01/03 09:24:28.370165,  0] ../../lib/util/charset/codepoints.c:16649(get_conv_handle) 
Jan 03 09:24:28 LibreELEC smbd[1149]:   dos charset 'CP850' unavailable - using ASCII 
Jan 03 09:24:28 LibreELEC kernel: device offline error, dev sda, sector 0 op 0x1:(WRITE) flags 0x800 phys_seg 0 prio class 2 
Jan 03 09:24:28 LibreELEC kernel: EXT4-fs (sda2): shut down requested (2) 
Jan 03 09:24:28 LibreELEC kernel: Aborting journal on device sda2-8. 
Jan 03 09:24:28 LibreELEC kernel: device offline error, dev sda, sector 1089538 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 2 
Jan 03 09:24:28 LibreELEC kernel: device offline error, dev sda, sector 1089538 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 2 
Jan 03 09:24:28 LibreELEC kernel: Buffer I/O error on dev sda2, logical block 16385, lost sync page write 
Jan 03 09:24:28 LibreELEC kernel: JBD2: I/O error when updating journal superblock for sda2-8. 
Jan 03 09:24:28 LibreELEC systemd[1]: Failed to resolve symlink /storage/.config/system.d, ignoring: Input/output error 
Jan 03 09:24:28 LibreELEC systemd[1]: Failed to open "/storage/.config/system.d", ignoring: Input/output error 
Jan 03 09:24:28 LibreELEC kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache 
Jan 03 09:24:28 LibreELEC kernel: sd 0:0:0:0: [sda] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=DRIVER_OK 
Jan 03 09:24:28 LibreELEC kernel: usb 4-1: Disable of device-initiated U1 failed. 
Jan 03 09:24:28 LibreELEC kernel: usb 4-1: Disable of device-initiated U2 failed. 
Jan 03 09:24:28 LibreELEC kernel: usb 4-1: Enable of device-initiated U1 failed. 
Jan 03 09:24:28 LibreELEC kernel: usb 4-1: Enable of device-initiated U2 failed. 
Jan 03 09:24:28 LibreELEC kernel: usb 4-1: reset SuperSpeed USB device number 2 using xhci-hcd 
Jan 03 09:24:28 LibreELEC kernel: scsi host1: uas 
Jan 03 09:24:28 LibreELEC kernel: scsi 1:0:0:0: Direct-Access     JMicron  Tech             0214 PQ: 0 ANSI: 6 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] 937703088 512-byte logical blocks: (480 GB/447 GiB) 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] 4096-byte physical blocks 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] Write Protect is off 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] Mode Sense: 53 00 00 08 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] Preferred minimum I/O size 4096 bytes 
Jan 03 09:24:28 LibreELEC kernel: sd 1:0:0:0: [sdb] Optimal transfer size 33553920 bytes not a multiple of preferred minimum block size (4096 bytes) 
Jan 03 09:24:29 LibreELEC kernel:  sdb: sdb1 sdb2 
Jan 03 09:24:29 LibreELEC kernel: sd 1:0:0:0: [sdb] Attached SCSI disk 
Jan 03 09:24:29 LibreELEC systemd[1]: Created slice system-udevil\x2dmount.slice. 
Jan 03 09:24:29 LibreELEC systemd[1]: Starting udevil-mount@-dev-sdb1.service... 
Jan 03 09:24:29 LibreELEC systemd[1]: Starting udevil-mount@-dev-sdb2.service... 
Jan 03 09:24:29 LibreELEC udevil[1171]: Mounted /dev/sdb1 at /media/LIBREELEC 
Jan 03 09:24:29 LibreELEC systemd[1]: Finished udevil-mount@-dev-sdb1.service. 
Jan 03 09:24:29 LibreELEC udevil[1172]: Mounted /dev/sdb2 at /media/STORAGE 
Jan 03 09:24:29 LibreELEC kernel: EXT4-fs (sdb2): recovery complete 
Jan 03 09:24:29 LibreELEC kernel: EXT4-fs (sdb2): mounted filesystem 69675956-de9a-48ac-b10c-13fcd7f42e78 r/w with ordered data mode. Quota mode: disabled. 
Jan 03 09:24:29 LibreELEC systemd[1]: Finished udevil-mount@-dev-sdb2.service. 
Jan 03 09:24:30 LibreELEC kodi.sh[835]: [*** LOG ERROR #0001 ***] [2024-01-03 09:24:30] [general] Failed flush to file /storage/.kodi/temp/kodi.log: Input/output error 
Jan 03 09:25:44 LibreELEC sshd[1227]: sshd: no hostkeys available -- exiting. 
Jan 03 09:26:21 LibreELEC sshd[1247]: sshd: no hostkeys available -- exiting.

Display More

So that seems to be what happens when the drive unmounts. That final error is me trying to ssh with a third terminal

Clipps · January 3, 2024 at 9:42 AM

And it looks like I may not be alone with this issue (as a sanity check): https://forums.raspberrypi.com/viewtopic.php?t=361171

Pi 5 xHCI controller fails during disk-to-disk copy behind a hub · Issue #5753 · raspberrypi/linux

Describe the bug Doing an rsync between two spinning rust drives attached to the same hub causes a suspected controller lockup. The symptom is [ 194.841355]…

github.com

How do I do the equivalent of: sudo rpi-update pulls/5778 on libreelec please?

**chewitt** · January 3, 2024 at 11:48 AM

LE tracks the upstream Pi repo's closely so if using any nightly images we're probably already on the latest update for kernel and firmware. You can update the boot eeprom with "rpi-eeprom-update -a" but there's nothing else (USB firmware is an RPi4 only thing).