Cannot restore specific AppVM due to unknown error

[0x9060]

How to file a helpful issue

Qubes OS release

4.2.3

Brief summary

Cannot restore a specific AppVM due to Input/Output error. Error messages reference diagnostic files that do not exist.

Steps to reproduce

1. Create an AppVM (here named private) based on a debian-12 template. I have no problems restoring the template itself, nor other AppVMs using the same template. Then perform following steps on the AppVM.
2. Install Trader Workstation 10.33. Installation file is fetched from https://www.interactivebrokers.com/en/trading/tws-offline-installers.php on a dispVM and copied to AppVM
3. Install radicale_storage_decsync, using pip3 install --upgrade --break-system-packages radicale_storage_decsync
4. Make a systemd user process process for radicale using the process described here.
5. Synchronize 3 different directories with my federated devices using syncthing. This causes the AppVM disk usage to grow to about 50,000 MiB.

Besides this, there are only minor tweaks I do to the AppVM, such as setting up Thunderbird, adding my Emacs config, Firefox tweaks...

I have successfully backed up and restored this AppVM dozens of times, most recently on October 3, 2024. I have not installed any other software on the AppVM since then. The only difference I can conceive of is the contents of the syncthing folders, and any other changes resulting from normal template updates (which does not cause issues with restoring other AppVMs depending on the same template)

I have totally rebuilt this AppVM yesterday, and proceeded to try to backup and [test to verify] restore. Then I hit these problems:

• I shut down the AppVM to reduce any chance of volatile data or memory. I am able to create the backup for this AppVM without a problem.
• Then I try to restore the AppVM, using the test restore to verify backup integrity option. I receive the following error:

Something like:

unable to read the qubes backup file /media/user/UUID/Qubes/qubes-backup-DATETIME. Starting Restorecopy... Performing restore from backup file to STDOUT... ntar2qfile: Fatal error: Copying file vm4/private.img.459.enc: Error reading (error type: Input/output error). Partially restored files left in /var/tmp/restore_*, investigate them and/or clean them up

The last sentence here is curious. There are no files in /var/tmp/restore_*. The only directories in /var/tmp/ are systemd directories, all containing an empty /tmp/` directory within. I have checked on dom0, this private AppVM, and my vault VM (where my backup USB is mounted for performing these backup/restores).

• Then I try again to restore the AppVM, without selecting the test restore to verify backup integrity option. I receive a slightly different error message, but this is not much more helpful for me. I cannot determine the cause of the failed restoration.

The error message is generally the same, without references to /var/tmp/.

An AppVM is created with the expected name (private), but it does not contain any of my files in the Home directory. It essentially looks like a newly created AppVM with the same Qubes settings.

Expected behavior

Restore the backup without failures. Produce a helpful error message.

Actual behavior

Restoring the backup fails, and the error messages lead me to dead ends.

[rustybird]

There's an I/O error in there, originating from your vault VM that's accessing the backup file. Anything interesting in its kernel logs while this is happening?

[rustybird]

Partially restored files left in /var/tmp/restore_*, investigate them and/or clean them up

The last sentence here is curious. There are no files in /var/tmp/restore_*.

Yeah that message is outdated, ~/QubesIncoming/backup#restore-* is the correct location.

-> QubesOS/qubes-manager#402

[0x9060]

There's an I/O error in there, originating from your vault VM that's accessing the backup file. Anything interesting in its kernel logs while this is happening?

Yes, there are the following errors:

Here's the text, if you prefer that:

[ 3908.266771] vhci_hcd: unlink->seqnum 2203386
[ 3908.266785] vhci_hcd: urb->status -104
[ 3908.380042] usb 2-1: SetAddress Request (2) to port 0
[ 3908.380058] usb 2-1: reset SuperSpeed USB device number 2 using vhci_hcd
[ 3908.405120] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK cmd_age=30s
[ 3908.405146] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 aa 06 88 00 00 01 00 00 00
[ 3908.405163] I/O error, dev sda, sector 4138337928 op 0x0:(READ) flags 0x80700 phys_seg 32 prio class 2
[ 3938.474312] vhci_hcd: unlink->seqnum 2203397
[ 3938.474325] vhci_hcd: urb->status -104
[ 3938.588002] usb 2-1: SetAddress Request (2) to port 0
[ 3938.588024] usb 2-1: reset SuperSpeed USB device number 2 using vhci_hcd
[ 3968.678659] vhci_hcd: unlink->seqnum 2203408
[ 3968.678674] vhci_hcd: urb->status -104
[ 3968.791954] usb 2-1: SetAddress Request (2) to port 0
[ 3968.791976] usb 2-1: reset SuperSpeed USB device number 2 using vhci_hcd
[ 3980.719774] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=3s
[ 3980.719796] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 3980.719806] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 3980.719817] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 aa 07 88 00 00 01 00 00 00
[ 3980.719836] critical medium error, dev sda, sector 4138338184 op 0x0:(READ) flags 0x80700 phys_seg 32 prio class 2
[ 3995.541338] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 3995.541369] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 3995.541384] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 3995.541400] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 aa 07 58 00 00 00 08 00 00
[ 3995.541425] critical medium error, dev sda, sector 4138338136 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4007.509104] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 4007.509124] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 4007.509135] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 4007.509144] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 aa 07 a0 00 00 00 08 00 00
[ 4007.509156] critical medium error, dev sda, sector 4138338208 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4310.148601] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 4310.148630] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 4310.148646] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 4310.148662] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 c6 90 48 00 00 00 10 00 00
[ 4310.148689] critical medium error, dev sda, sector 4140208200 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2
[ 4312.981565] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 4312.981585] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 4312.981595] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 4312.981604] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 c6 90 58 00 00 00 10 00 00
[ 4312.981615] critical medium error, dev sda, sector 4140208216 op 0x0:(READ) flags 0x80700 phys_seg 2 prio class 2
[ 4315.769986] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 4315.770017] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 4315.770033] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 4315.770055] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 c6 90 50 00 00 00 08 00 00
[ 4315.770076] critical medium error, dev sda, sector 4140208208 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4318.570472] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 4318.570504] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 4318.570520] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 4318.570537] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 c6 90 50 00 00 00 08 00 00
[ 4318.570557] critical medium error, dev sda, sector 4140208208 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2
[ 4321.369912] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_OK cmd_age=2s
[ 4321.369944] sd 0:0:0:0: [sda] tag#0 Sense Key : Medium Error [current]
[ 4321.369962] sd 0:0:0:0: [sda] tag#0 Add. Sense: Unrecovered read error
[ 4321.369978] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 f6 c6 90 50 00 00 00 08 00 00
[ 4321.369999] critical medium error, dev sda, sector 4140208208 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2

[0x9060]

Partially restored files left in /var/tmp/restore_*, investigate them and/or clean them up

The last sentence here is curious. There are no files in /var/tmp/restore_*.

Yeah that message is outdated, ~/QubesIncoming/backup#restore-* is the correct location.

-> QubesOS/qubes-manager#402

There are no files in ~/QubesIncoming/backup#restore-*, not in the Vault VM, nor in the fresh AppVM ("private") that was created as a result of this failed restore.

[rustybird]

[ 3908.405163] I/O error, dev sda, sector 4138337928 op 0x0:(READ) flags 0x80700 phys_seg 32 prio class 2

Probably a hardware error from your USB drive?

If you want to rule out that it's a problem with USB forwarding, you could forward the drive as a block device instead (and then look for kernel errors in sys-usb too), which is usually preferable anyway as it's more robust and there's less attack surface.

There are no files in ~/QubesIncoming/backup#restore-*, not in the Vault VM, nor in the fresh AppVM ("private")

That location is in dom0.