Attempting to restart sys-usb in a script disables the usb keyboard and mouse and also the laptop keyboard and touchpad, but not at the command line

1of7 · October 12, 2024, 12:10am

When restarting sys-usb after a template update sys-usb will shutdown but then all functionality of the usb keyboard and mouse is lost along with the keyboard and touchpad on the laptop. Shutting down/starting sys-usb in a script causes the failure but not if the commands are issued from the command line.

dmidecode shows the laptop keyboard and touchpad are using PS/2 ports.

Shutting down sys-usb and starting sys-usb from a command line works as expected; sys-usb restarts and keyboard and mouse functionality is restored.
If the exact same commands are issued in a script, then sys-usb fails to start after shutdown.

Also, using Qubes Update to update the associated template, default-dvm, results in the final step of the update to refresh sys-usb. Pressing the final button at the completion of the Qubes Update results in a notification that sys-usb is shutting down followed by a complete loss of usb keyboard, usb mouse and laptop keyboard and touchpad functionality.

The commands that work on the command line but not in a script are:
qvm-shutdown --wait sys-usb-def; qvm-prefs sys-usb-def template dvm-def; sleep 3; qvm-start sys-usb-def
=OR=
qvm-shutdown --wait sys-usb-def; qvm-prefs sys-usb-def template dvm-def; wait; qvm-start sys-usb-def

The system specs are:
Brand: ASUSTeK COMPUTER INC. Model: ASUS TUF Gaming A16 FA617NT_FA617NT


CPU: AMD Ryzen 7 7735HS with Radeon Graphics

Chipset: Advanced Micro Devices, Inc. [AMD] Family 17h-19h PCIe Root Complex [1022:14b5] (rev 01)

Graphics: Advanced Micro Devices, Inc. [AMD/ATI] Navi 33 [Radeon RX 7700S/7600/7600S/7600M XT/PRO W7600] [1002:7480] (rev c1) (prog-if 00 [VGA controller])

Advanced Micro Devices, Inc. [AMD/ATI] Rembrandt [Radeon 680M] [1002:1681] (rev 0a) (prog-if 00 [VGA controller])

RAM: 64763 Mb

apparatus · October 12, 2024, 9:13am

Try to increase the sleep time for a test, maybe there is some race condition and the sys-usb preferences are not fully updated when you try to start it yet:

#!/bin/sh
qvm-shutdown --wait sys-usb-def; qvm-prefs sys-usb-def template dvm-def;
sleep 30; qvm-start sys-usb-def

1of7 · October 14, 2024, 12:04am

No luck. sleep 70 was tried but the same result.

There’s a notification that sys-usb is starting, then the notification disappears with no response from the usb keyboard/mouse (and the laptop keyboard/touchpad if the script is executed using the usb keyboard).

A rough paraphrase of journalctl -b -1 | grep failed

vm.sys-usb: Start failed: cannot connect to qrexec agent for 60 secs, see /var/log/xen/console/guest-sys-usb.log

The period corresponding to the journalctl time stamp in the guest-sys-usb.log is empty.

As stated above, the commands will execute in a script if the script is lauched using the laptop keyboard and locks up if launched from the usb keyboard.

Other installs of Qubes on towers and desktops (> 2 years old) do not show this affect; only on this recent laptop.

With the complete loss of input, only a cold shutdown and boot will restore the keyboards/touchpad/mouse as input devices.

Thanks for the idea

apparatus · October 14, 2024, 5:08pm

Maybe it’s some specific USB controller that is causing this issue?
Try to create multiple test sys-usb qubes with only 1 USB controller attached to them and try to restart them one by one to see which one will lead to the failed start.
Maybe this one failing USB controller won’t cause all your USB devices and your PS/2 keyboard/mouse to stop working and you’ll be able to debug the problem further with keyboard available.

1of7 · October 15, 2024, 1:12am

Only one external USB port is used for the USB keyboard/mouse fob.
The two conditions were tested and the journalctl output was reviewed.

The run made from the laptop keyboard successfully returned to input from either the laptop or usb keyboard.
The run from the usb keyboard did not and the ability to input was lost.

Excerpts of the 284K log are below.
Here is the script modified to print out the time at which each step is taken so the events could be located with journalctl;

File: test_usb_shutdown_restart.sh

#!/bin/bash date; qvm-shutdown --wait sys-usb; date; qvm-prefs sys-usb template default-dvm; date; sleep 3; date; qvm-start sys-usb; date

The script was executed as follows:

$ ./test_usb_shutdown_restart.sh | tee -a test_usb_shutdown_restart.sh.log.YYYYMMDD_HHMMSS

Where YYYYMMDD_HHMMSS is the date and time of the script execution.

The script was run using the laptop keyboard, then run using the usb keyboard.

The times associated with the run from the laptop keyboard are:
Mon Oct 14 02:59:20 PM EDT 2024
Mon Oct 14 02:59:23 PM EDT 2024
Mon Oct 14 02:59:23 PM EDT 2024
Mon Oct 14 02:59:26 PM EDT 2024
Mon Oct 14 02:59:36 PM EDT 2024

The times associated with run using the USB keyboard are:

Mon Oct 14 03:10:46 PM EDT 2024
Mon Oct 14 03:10:49 PM EDT 2024
Mon Oct 14 03:10:49 PM EDT 2024
Mon Oct 14 03:10:52 PM EDT 2024
**** Laptop/USB Keyboards/Mouse/Touchpad locked up

The excerpts of the journalctl log for the laptop keyboard run are:
…
Oct 14 14:58:21 dom0 systemd[4048]: Started gvfs-metadata.service - Virtual filesystem metadata service.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:23 dom0 qubesd[2891]: socket.send() raised exception.
Oct 14 14:59:26 dom0 qubesd[2891]: vm.sys-usb: Starting sys-usb
Oct 14 14:59:26 dom0 systemd[4048]: Starting grub-boot-success.service - Mark boot as successful…
Oct 14 14:59:26 dom0 systemd[4048]: Finished grub-boot-success.service - Mark boot as successful.
Oct 14 14:59:26 dom0 lvm[1754]: No longer monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 14:59:26 dom0 lvm[1754]: Monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 14:59:26 dom0 lvm[1754]: No longer monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 14:59:26 dom0 lvm[1754]: Monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 14:59:27 dom0 kernel: loop0: detected capacity change from 0 to 1215544
Oct 14 14:59:27 dom0 kernel: loop1: detected capacity change from 0 to 1215544
Oct 14 14:59:27 dom0 kernel: pciback 0000:77:00.3: xen_pciback: vpci: assign to virtual slot 0
Oct 14 14:59:27 dom0 kernel: pciback 0000:77:00.3: registering for 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:77:00.4: xen_pciback: vpci: assign to virtual slot 0 func 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:77:00.4: registering for 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.0: xen_pciback: vpci: assign to virtual slot 1
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.0: registering for 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.3: xen_pciback: vpci: assign to virtual slot 1 func 3
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.3: registering for 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.4: xen_pciback: vpci: assign to virtual slot 1 func 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.4: registering for 4
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.5: xen_pciback: vpci: assign to virtual slot 1 func 5
Oct 14 14:59:27 dom0 kernel: pciback 0000:78:00.5: registering for 4
Oct 14 14:59:27 dom0 kernel: xen-blkback: backend/vbd/4/51712: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:27 dom0 kernel: xen-blkback: backend/vbd/4/51728: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen-blkback: backend/vbd/4/51744: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :24
Oct 14 14:59:27 dom0 kernel: xen-blkback: backend/vbd/4/51760: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :25
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :26
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :33
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:27 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 14:59:27 dom0 kernel: Already setup the GSI :34
Oct 14 14:59:28 dom0 qubesd[2891]: vm.sys-usb: Setting Qubes DB info for the VM
Oct 14 14:59:28 dom0 qubesd[2891]: vm.sys-usb: Starting Qubes DB
Oct 14 14:59:28 dom0 audit[4963]: CRED_ACQ pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 kernel: audit: type=1103 audit(1728932368.879:293): pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 runuser[4963]: pam_unix(runuser:session): session opened for user auser(uid=1000) by (uid=0)
Oct 14 14:59:28 dom0 kernel: audit: type=1105 audit(1728932368.880:294): pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 audit[4963]: USER_START pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 runuser[4963]: pam_unix(runuser:session): session closed for user auser
Oct 14 14:59:28 dom0 audit[4963]: USER_END pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 audit[4963]: CRED_DISP pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 kernel: audit: type=1106 audit(1728932368.888:295): pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 kernel: audit: type=1104 audit(1728932368.888:296): pid=4963 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 qubesd[2891]: vm.sys-usb: Activating the sys-usb VM
Oct 14 14:59:28 dom0 audit[4967]: CRED_ACQ pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 kernel: audit: type=1103 audit(1728932368.900:297): pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 runuser[4967]: pam_unix(runuser:session): session opened for user auser(uid=1000) by (uid=0)
Oct 14 14:59:28 dom0 audit[4967]: USER_START pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:28 dom0 kernel: audit: type=1105 audit(1728932368.902:298): pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:30 dom0 kernel: xen-blkback: backend/vbd/3/51712: using 2 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:30 dom0 kernel: xen-blkback: backend/vbd/3/51728: using 2 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:30 dom0 kernel: xen-blkback: backend/vbd/3/51744: using 2 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:30 dom0 kernel: xen-blkback: backend/vbd/3/51760: using 2 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 14:59:33 dom0 runuser[4967]: pam_unix(runuser:session): session closed for user auser
Oct 14 14:59:33 dom0 kernel: audit: type=1106 audit(1728932373.972:299): pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:33 dom0 kernel: audit: type=1104 audit(1728932373.972:300): pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:33 dom0 audit[4967]: USER_END pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:33 dom0 audit[4967]: CRED_DISP pid=4967 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:36 dom0 qrexec-policy-daemon[2895]: qrexec: qubes.InputKeyboard+: sys-usb → @adminvm: allowed to dom0
Oct 14 14:59:36 dom0 audit: BPF prog-id=54 op=LOAD
Oct 14 14:59:36 dom0 audit: BPF prog-id=55 op=LOAD
Oct 14 14:59:36 dom0 audit: BPF prog-id=56 op=LOAD
Oct 14 14:59:36 dom0 kernel: audit: type=1334 audit(1728932376.186:301): prog-id=54 op=LOAD
Oct 14 14:59:36 dom0 kernel: audit: type=1334 audit(1728932376.187:302): prog-id=55 op=LOAD
Oct 14 14:59:36 dom0 kernel: audit: type=1334 audit(1728932376.187:303): prog-id=56 op=LOAD
Oct 14 14:59:36 dom0 systemd[1]: Starting systemd-hostnamed.service - Hostname Service…
Oct 14 14:59:36 dom0 systemd[1]: Started systemd-hostnamed.service - Hostname Service.
Oct 14 14:59:36 dom0 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=systemd-hostnamed comm=“systemd” exe=“/usr/lib/systemd/systemd” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:36 dom0 kernel: audit: type=1130 audit(1728932376.308:304): pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=systemd-hostnamed comm=“systemd” exe=“/usr/lib/systemd/systemd” hostname=? addr=? terminal=? res=success’
Oct 14 14:59:36 dom0 kernel: input: sys-usb: Logitech Wireless Mouse as /devices/virtual/input/input19
Oct 14 14:59:36 dom0 systemd-logind[2277]: Watching system buttons on /dev/input/event15 (sys-usb: Logitech Wireless Mouse)
Oct 14 14:59:37 dom0 qrexec-policy-daemon[2895]: qrexec: qubes.InputKeyboard+: sys-usb → @adminvm: allowed to dom0
Oct 14 14:59:37 dom0 kernel: input: sys-usb: Logitech K540e as /devices/virtual/input/input20
Oct 14 14:59:37 dom0 systemd-logind[2277]: Watching system buttons on /dev/input/event16 (sys-usb: Logitech K540e)
Oct 14 14:59:40 dom0 qrexec-policy-daemon[2895]: qrexec: qubes.GetDate+nanoseconds: sys-usb → @default: allowed to dom0
Oct 14 14:59:40 dom0 qrexec-policy-daemon[2895]: qrexec: qubes.WindowIconUpdater+: sys-usb → @adminvm: allowed to dom0
…

The excerpts of the journalctl log for the USB keyboard run are:

…
Oct 14 15:02:45 dom0 systemd[4048]: Finished systemd-tmpfiles-clean.service - Cleanup of User’s Temporary Files and Directories.
Oct 14 15:10:52 dom0 qubesd[2891]: vm.sys-usb: Starting sys-usb
Oct 14 15:10:52 dom0 lvm[1754]: No longer monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 15:10:53 dom0 lvm[1754]: Monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 15:10:53 dom0 lvm[1754]: No longer monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 15:10:53 dom0 lvm[1754]: Monitoring thin pool qubes_dom0-vm–pool-tpool.
Oct 14 15:10:53 dom0 kernel: loop0: detected capacity change from 0 to 1215544
Oct 14 15:10:53 dom0 kernel: loop1: detected capacity change from 0 to 1215544
Oct 14 15:10:53 dom0 kernel: pciback 0000:77:00.3: xen_pciback: vpci: assign to virtual slot 0
Oct 14 15:10:53 dom0 kernel: pciback 0000:77:00.3: registering for 6
Oct 14 15:10:53 dom0 kernel: pciback 0000:77:00.4: xen_pciback: vpci: assign to virtual slot 0 func 4
Oct 14 15:10:53 dom0 kernel: pciback 0000:77:00.4: registering for 6
Oct 14 15:10:53 dom0 kernel: pciback 0000:78:00.0: xen_pciback: vpci: assign to virtual slot 1
Oct 14 15:10:53 dom0 kernel: pciback 0000:78:00.0: registering for 6
Oct 14 15:10:53 dom0 kernel: pciback 0000:78:00.3: xen_pciback: vpci: assign to virtual slot 1 func 3
Oct 14 15:10:53 dom0 kernel: pciback 0000:78:00.3: registering for 6
Oct 14 15:10:54 dom0 kernel: pciback 0000:78:00.4: xen_pciback: vpci: assign to virtual slot 1 func 4
Oct 14 15:10:54 dom0 kernel: pciback 0000:78:00.4: registering for 6
Oct 14 15:10:54 dom0 kernel: pciback 0000:78:00.5: xen_pciback: vpci: assign to virtual slot 1 func 5
Oct 14 15:10:54 dom0 kernel: pciback 0000:78:00.5: registering for 6
Oct 14 15:10:54 dom0 kernel: xen-blkback: backend/vbd/6/51712: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen-blkback: backend/vbd/6/51728: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 24 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :24
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 25 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :25
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 26 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :26
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 33 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :33
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen: registering gsi 34 triggering 0 polarity 1
Oct 14 15:10:54 dom0 kernel: Already setup the GSI :34
Oct 14 15:10:54 dom0 kernel: xen-blkback: backend/vbd/6/51744: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 15:10:54 dom0 kernel: xen-blkback: backend/vbd/6/51760: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 14 15:10:55 dom0 qubesd[2891]: vm.sys-usb: Setting Qubes DB info for the VM
Oct 14 15:10:55 dom0 qubesd[2891]: vm.sys-usb: Starting Qubes DB
Oct 14 15:10:55 dom0 audit[5655]: CRED_ACQ pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 kernel: audit: type=1103 audit(1728933055.279:309): pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 runuser[5655]: pam_unix(runuser:session): session opened for user auser(uid=1000) by (uid=0)
Oct 14 15:10:55 dom0 kernel: audit: type=1105 audit(1728933055.280:310): pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 audit[5655]: USER_START pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 runuser[5655]: pam_unix(runuser:session): session closed for user auser
Oct 14 15:10:55 dom0 audit[5655]: USER_END pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 audit[5655]: CRED_DISP pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 kernel: audit: type=1106 audit(1728933055.288:311): pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 kernel: audit: type=1104 audit(1728933055.288:312): pid=5655 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 qubesd[2891]: vm.sys-usb: Activating the sys-usb VM
Oct 14 15:10:55 dom0 audit[5659]: CRED_ACQ pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 kernel: audit: type=1103 audit(1728933055.299:313): pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 runuser[5659]: pam_unix(runuser:session): session opened for user auser(uid=1000) by (uid=0)
Oct 14 15:10:55 dom0 kernel: audit: type=1105 audit(1728933055.301:314): pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:10:55 dom0 audit[5659]: USER_START pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:45 dom0 systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories…
Oct 14 15:11:46 dom0 systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.
Oct 14 15:11:46 dom0 systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories.
Oct 14 15:11:46 dom0 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=systemd-tmpfiles-clean comm=“systemd” exe=“/usr/lib/systemd/systemd” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:46 dom0 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=systemd-tmpfiles-clean comm=“systemd” exe=“/usr/lib/systemd/systemd” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:46 dom0 kernel: audit: type=1130 audit(1728933106.299:315): pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=systemd-tmpfiles-clean comm=“systemd” exe=“/usr/lib/systemd/systemd” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:46 dom0 kernel: audit: type=1131 audit(1728933106.299:316): pid=1 uid=0 auid=4294967295 ses=4294967295 msg=‘unit=systemd-tmpfiles-clean comm=“systemd” exe=“/usr/lib/systemd/systemd” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:55 dom0 runuser[5659]: pam_unix(runuser:session): session closed for user auser
Oct 14 15:11:55 dom0 kernel: audit: type=1106 audit(1728933115.359:317): pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:55 dom0 kernel: audit: type=1104 audit(1728933115.359:318): pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:55 dom0 audit[5659]: USER_END pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:55 dom0 audit[5659]: CRED_DISP pid=5659 uid=0 auid=4294967295 ses=4294967295 msg=‘op=PAM:setcred grantors=pam_rootok acct=“auser” exe=“/usr/sbin/runuser” hostname=? addr=? terminal=? res=success’
Oct 14 15:11:55 dom0 qubesd[2891]: vm.sys-usb: Start failed: Cannot connect to qrexec agent for 60 seconds, see /var/log/xen/console/guest-sys-usb.log for details

apparatus · October 15, 2024, 6:20am

Do you mean you have different result when you press Enter key to execute the script in dom0 terminal on laptop keyboard and on USB keyboard?
Maybe the pressed Enter key on the USB keyboard when you shut down the sys-usb is causing some issue. Try to change the script to this:

#!/bin/bash
sleep 3; date; qvm-shutdown --wait sys-usb; date; qvm-prefs sys-usb template default-dvm; date; sleep 3; date; qvm-start sys-usb; date

And don’t press any keys on the USB keyboard after pressing and releasing the Enter key to run the script.

Also check the log in /var/log/xen/console/guest-sys-usb-dm.log.

1of7 · October 16, 2024, 1:15am

The laptop and usb keyboard locked up after modifying the script to start with sleep 3 and only hitting the enter key on the usb keyboard.

Entries in /var/log/xen/console/guest-sys-usb-dm.log for the time periods recorded by the script are as follows:

$ cat test_usb_shutdown_restart.sh.log.20241015_1954

Tue Oct 15 07:54:27 PM EDT 2024
Tue Oct 15 07:54:30 PM EDT 2024
Tue Oct 15 07:54:30 PM EDT 2024
Tue Oct 15 07:54:33 PM EDT 2024

$ cat guest-sys-usb-dm.log-20241015_2004_excerpt

[2024-10-15 19:54:28] {“timestamp”: {“seconds”: 1729036468, “microseconds”: 981963}, “event”: “RESET”,
“data”: {“guest”: true, “reason”: “guest-reset”}}
[2024-10-15 19:54:29] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00
[2024-10-15 19:54:29] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00
[2024-10-15 19:54:29] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00
[2024-10-15 19:54:29] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00
[2024-10-15 19:54:29] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00
[2024-10-15 19:54:29] pcifront pci-0: Rescanning PCI Frontend Bus 0000:00
[2024-10-15 19:54:34] Logfile Opened
NOTE: Last entry [2024-10-15 19:54:34] is after cold shutdown and boot.

It’s as if the usb device is not persistent between sys-usb restarts.
I.E. man qvm-device
…
attach
–persistent, -p
Attach device persistently, which means have it attached also after qube restart.
…

Could it be that the usb keyboard/mouse is not attached using the -p option to sys-usb when the service is created during the OS install?

apparatus · October 16, 2024, 7:22am

No idea why it fails if you press Enter on a USB keyboard but it works if you press the enter on the laptop keyboard.
Is that the only difference or maybe you’re disconnecting your USB keyboard when you run the script using the laptop keyboard?

No, the USB PCI controller is attached persistently to your sys-usb, hotplugging PCI devices it not supported.

1of7 · October 16, 2024, 5:52pm

Not the pci USB controller, but the attached USB device.

[auser**@dom0**]$ qvm-usb list
BACKEND:DEVID DESCRIPTION USED BY … sys-usb:4-1 046d:c534_Logitech_USB_Receiver …

[user@sys-usb ~]$ lsusb
…
Bus 004 Device 002: ID 046d:c534 Logitech, Inc. Nano Receiver
…
It appears the PCI bus is available for scanning, but the device is not found.

apparatus · October 17, 2024, 5:16pm

USB devices are not attached to sys-usb from anywhere, the USB devices are connected to USB PCI controller that is attached to sys-usb so the USB devices are initialized and available directly in the sys-usb itself.
Your problem is that sys-usb qube can’t start with USB PCI controller attached to it for some reason.

1of7 · October 23, 2024, 11:43pm

Thanks for the insights. I’ve been finding configuring laptops with integrated and discrete graphics cards and USB keyboard/mouse external input to be very difficult. I even looked at System 76 laptops with coreboot type firmware but a rep stated that they don’t support qubes-os and it’s pretty much up to the end-user to figure out.
This particular use case is to use the laptop’s hardware for the operating system but without using the laptop keyboard, TouchPad, or display; but using an external unsmart tv/monitor and a USB full keyboard/mouse.
It’s been possible with towers, desktops, mini pcs with discrete video cards, even older laptops, but not more current laptops.
The laptop will go on the road so having the use case ability is a big plus.
Thanks again for your input.
Gotta run, snow is expected soon, and there’s still trees to cut down…