Qubes 4.1 update (2022-09-07) broke my sys-usb

I just updated my system this morning (2022-09-07) and rebooted because I saw some Xen updates included. When my system came back up sys-usb failed to start with error:

qrexec-sys-usb.log

2022-09-07 11:43:18.090 qrexec-daemon[29201]: qrexec-daemon.c:340:init: cannot connect to qrexec agent: No such file or directory

Other VM’s using the same template have no problem starting nor does sys-usb when there are no devices assigned to it. qrexec-agent obviously exists in the template but I can’t even get a command shell to look for it when any devices are attached. Running in debug mode is no help because it just quickly exits with no obvious messages on the debug console. Its not even waiting for the qrexec_timeout!

If I remove both controller boards from sys-usb’s configuration sys-usb starts up just fine, but if I add either device (USB or SATA) back to it then it refuses to start and shuts down with this same error. Its obviously not the board/drivers because neither one works and they are completely different hardware and drivers.

The guest-sys-usb-dm.log says very little about what might be wrong:

[2022-09-07 11:43:13] [00:06.0] xen_pt_realize: Assigning real physical device 02:00.0 to devfn 0x30
[2022-09-07 11:43:13] [00:06.0] xen_pt_register_regions: IO region 0 registered (size=0x00002000 base_addr=0xee700000 type: 0x4)
[2022-09-07 11:43:13] [00:06.0] xen_pt_config_reg_init: Offset 0x000e mismatch! Emulated=0x0080, host=0x0000, syncing to 0x0000.
[2022-09-07 11:43:13] [00:06.0] xen_pt_config_reg_init: Offset 0x0010 mismatch! Emulated=0x0000, host=0xee700004, syncing to 0xee700004.
[2022-09-07 11:43:13] [00:06.0] xen_pt_config_reg_init: Offset 0x0052 mismatch! Emulated=0x0000, host=0x01c3, syncing to 0x0003.
[2022-09-07 11:43:13] [00:06.0] xen_pt_config_reg_init: Offset 0x0072 mismatch! Emulated=0x0000, host=0x0086, syncing to 0x0080.
[2022-09-07 11:43:14] [00:06.0] xen_pt_config_reg_init: Offset 0x00a4 mismatch! Emulated=0x0000, host=0x8fc0, syncing to 0x8fc0.
[2022-09-07 11:43:14] [00:06.0] xen_pt_config_reg_init: Offset 0x00aa mismatch! Emulated=0x0000, host=0x0010, syncing to 0x0010.
[2022-09-07 11:43:14] [00:06.0] xen_pt_config_reg_init: Offset 0x00b2 mismatch! Emulated=0x0000, host=0x1012, syncing to 0x1012.
[2022-09-07 11:43:14] [00:06.0] xen_pt_pci_intx: intx=1
[2022-09-07 11:43:14] [00:06.0] xen_pt_realize: Real physical device 02:00.0 registered successfully
[2022-09-07 11:43:14] written 34 bytes to vchan
[2022-09-07 11:43:14] written 2048 bytes to vchan
[2022-09-07 11:43:14] written 969 bytes to vchan
[2022-09-07 11:43:14] written 110 bytes to vchan
[2022-09-07 11:43:14] written 34 bytes to vchan
[2022-09-07 11:43:14] written 34 bytes to vchan
[2022-09-07 11:43:14] processing error - resetting ehci HC
[2022-09-07 11:43:14] random: crng init done
[2022-09-07 11:43:15] {“timestamp”: {“seconds”: 1662565395, “microseconds”: 466325}, “event”: “RESET”, “data”: {“guest”: true, “reason”: “guest-reset”}}
[2022-09-07 11:43:15] {“timestamp”: {“seconds”: 1662565395, “microseconds”: 467327}, “event”: “RESET”, “data”: {“guest”: true, “reason”: “guest-reset”}}
[2022-09-07 11:43:15] {“timestamp”: {“seconds”: 1662565395, “microseconds”: 495970}, “event”: “DEVICE_DELETED”, “data”: {“path”: “/machine/peripheral-anon/device[3]”}}
[2022-09-07 11:43:15] {“timestamp”: {“seconds”: 1662565395, “microseconds”: 496038}, “event”: “DEVICE_DELETED”, “data”: {“path”: “/machine/peripheral-anon/device[0]”}}
[2022-09-07 11:43:17] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00

guest-sys-usb.log says:
[2022-09-07 11:43:10] Logfile Opened

Dom0 dmesg says:
[ 524.073745] audit: type=1130 audit(1662562913.238:301): pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=qubes-vm@sys-usb comm=“systemd” exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed

Anyone have a clue here? Without a controller board there is little point in having a sys-usb if you can not even backup and restore with it. Fortunately my keyboard and mouse are not confined to it so my system is still somewhat functional otherwise.

Can you check /var/log/xen/console/hypervisor.log if you have some crash message related to this VM?

@marmarek

I looked at the console/hypervisor.log and there is nothing that stands out as an error message for this. After seeing your request I restarted the sys-usb again and didn’t see anything new get added to the hypervisor.log.

I created a new sys-usb HVM and moved the devices to that and was able to start it but the system seems very slow for some reason. I’m still trying to move my configuration over from the old to the new VM but its dog slow at the moment and I don’t see any maxed out CPU anywhere. Its just acting very weird today. It has frozen on me twice today and I had to do a hard shutdown to recover. Once when the non-locking screensaver blanked the screen and the second time when I was using the web in another AppVM to search for some answers.

When I started sys-usb dmesg put out these Xen/device related messeges:
[15525.724144] loop2: detected capacity change from 0 to 957080
[15526.884910] loop3: detected capacity change from 0 to 957080
[15526.999852] pciback 0000:06:00.0: xen_pciback: vpci: assign to virtual slot 0
[15527.001357] pciback 0000:06:00.0: registering for 14
[15527.212448] xen-blkback: backend/vbd/14/51712: using 1 queues, protocol 1 (x86_64-abi) persistent grants
[15527.215311] xen: registering gsi 16 triggering 0 polarity 1
[15527.215317] Already setup the GSI :16
[15527.215533] xen: registering gsi 16 triggering 0 polarity 1
[15527.215535] Already setup the GSI :16
[15527.215692] xen: registering gsi 16 triggering 0 polarity 1
[15527.215695] Already setup the GSI :16
[15527.215840] xen: registering gsi 16 triggering 0 polarity 1
[15527.215842] Already setup the GSI :16
[15527.215986] xen: registering gsi 16 triggering 0 polarity 1
[15527.215988] Already setup the GSI :16
[15527.216157] xen: registering gsi 16 triggering 0 polarity 1
[15527.216159] Already setup the GSI :16
[15527.216339] xen: registering gsi 16 triggering 0 polarity 1
[15527.216342] Already setup the GSI :16
[15527.216499] xen: registering gsi 16 triggering 0 polarity 1
[15527.216501] Already setup the GSI :16
[15527.243726] xen-blkback: backend/vbd/14/51728: using 1 queues, protocol 1 (x86_64-abi) persistent grants
[15527.267732] xen-blkback: backend/vbd/14/51744: using 1 queues, protocol 1 (x86_64-abi) persistent grants
[15527.290978] xen-blkback: backend/vbd/14/51760: using 1 queues, protocol 1 (x86_64-abi) persistent grants

Is there anything else to look at? I might have a pat forward but there appears to be another person with the same problem, so its not just me.