Disposable qubes preloaded after every suspend/resume

Hi,

I’ve upgraded my laptop to Qubes 4.3 a some time ago, and I’ve noticed that the disposable qubes are preloaded after every suspend/resume cycle. So right now I have ~10 disposable qubes running, but I certainly don’t need that many. Each disposable qube is getting ~3GB of RAM, which seems a bit high.

I ended up disabling preloading of disaposablw qubes in global config, and this behavior went away.

The expected behavior when suspending is:

  • Preloaded disposables are scheduled for deletion, I really mean scheduled, because suspend is normally fast and there will not be enough time for them to be deleted at this stage

The expected behavior when resuming is:

  • Old preloaded disposables are finally deleted and new ones are preloaded.

In other words, if you have configured that 2 disposables should be preloaded, you will still have 2 after resume, but fresh ones.

If this is not what is happening with you, can you please run the following, all in dom0:

qvm-features default-dvm preload-dispvm-max
qvm-features dom0 preload-dispvm-max
# And for any other disposable template you have configured to preload from.

Let’s see all running or paused disposables:

qvm-ls --class DispVM --running --paused

Now only preloaded disposables:

qvm-ls --prefs is_preload=True

Follow the journal:

sudo journalctl -f

And on another terminal:

sudo systemctl suspend

After some seconds, the computer should suspend, wait for the lights to indicate that, then click any key to resume, and share the output of every command.

Unfortunately, it seems I can no longer reproduce this. I’ve enabled the preloading in global config again, but now the disposable qubes are shutdown/started as expected (on suspend/resume), so I no longer see more than 2.

FWIW this is what I saw yesterday, before I disabled the preloading:

I don’t know it the disable/enable fixed some sort of config issue, or maybe there’s some other ingredient to this. I’ll keep it enabled and will report if it starts happening again.

OK, it happened again. Right now I have 5 disposable VMs:

I ran the commands, and I got this (this was before suspend/resume, I suppose that’s why the list of qubes is different from the screenshot):

tomas@dom0:~$ qvm-features default-dvm preload-dispvm-max
tomas@dom0:~$ qvm-features dom0 preload-dispvm-max
2
tomas@dom0:~$ qvm-ls --class DispVM --running --paused
NAME          STATE    CLASS   LABEL  TEMPLATE     NETVM
disp2899      Running  DispVM  red    default-dvm  sys-firewall
disp7058      Running  DispVM  red    default-dvm  sys-firewall
disp7526      Running  DispVM  red    default-dvm  sys-firewall
disp8724      Paused   DispVM  red    default-dvm  sys-firewall
disp9746      Paused   DispVM  red    default-dvm  sys-firewall
sys-firewall  Running  DispVM  green  default-dvm  sys-net
sys-usb       Running  DispVM  red    default-dvm  -
tomas@dom0:~$ qvm-ls  --prefs is_preload=True
NAME      STATE   CLASS   LABEL  TEMPLATE     NETVM
disp8724  Paused  DispVM  red    default-dvm  sys-firewall
disp9746  Paused  DispVM  red    default-dvm  sys-firewall

Here’s a snippet of journalctl for one suspend/resume cycle:

journalctl.log (58.7 KB)

There are some interesting python exceptions, related to the disposable VMs:

Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp9746, property-reset:xid, {'name': 'xid'}
...
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp9746'

Not sure what to make of it.

For the qubes that are running, I am not seeing all their logs, just this:

$ grep -E '(disp2899|disp7058|disp7526)' journalctl.log
Aug 04 21:08:17 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: disp7058 -> @default: allowed to dom0
Aug 04 21:08:17 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: disp2899 -> @default: allowed to dom0
Aug 04 21:08:17 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: disp7526 -> @default: allowed to dom0

While for the current preloaded disposables, I see this:

$ grep -E '(disp8724|disp9746)' journalctl.log
Aug 04 21:08:09 dom0 qubesd[11981]: INFO: vm.default-dvm: Removing excess qube(s) from preloaded list because system wants to suspend: 'disp9746, disp8724'
Aug 04 21:08:10 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp9746' in 'dom0'
Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp9746, property-reset:xid, {'name': 'xid'}
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp9746'
Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp9746, property-reset:stubdom_xid, {'name': 'stubdom_xid'}
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp9746'
Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp9746, property-reset:start_time, {'name': 'start_time'}
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp9746'
Aug 04 21:08:10 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp8724' in 'dom0'
Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp8724, property-reset:xid, {'name': 'xid'}
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp8724'
Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp8724, property-reset:stubdom_xid, {'name': 'stubdom_xid'}
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp8724'
Aug 04 21:08:10 dom0 widget-wrapper[36797]: Failed to handle event: disp8724, property-reset:start_time, {'name': 'start_time'}
Aug 04 21:08:10 dom0 widget-wrapper[36797]: qubesadmin.exc.QubesVMNotFoundError: No such domain: 'disp8724'
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp9746: Removing volume root: qubes_dom0/vm-disp9746-root
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp9746: Removing volume private: qubes_dom0/vm-disp9746-private
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp9746: Removing volume volatile: qubes_dom0/vm-disp9746-volatile
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp9746: Removing volume kernel: 7.0.14-1.fc41
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp8724: Removing volume root: qubes_dom0/vm-disp8724-root
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp8724: Removing volume private: qubes_dom0/vm-disp8724-private
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp8724: Removing volume volatile: qubes_dom0/vm-disp8724-volatile
Aug 04 21:08:11 dom0 qubesd[11981]: INFO: vm.disp8724: Removing volume kernel: 7.0.14-1.fc41

Can you share sudo journalctl (without -f, it will be a lot of information, so you can trim it to the first occurrence of the name of the oldest disposable.

Can you also share how you are using disposables? App menu? Script? Qrexec service in-qube such as qvm-open-in-dvm?

Can you run this command so I can see you qubes-manager version?

% rpm -qf /usr/lib/python3.13/site-packages/qubesmanager
qubes-manager-4.4.0-1.16.fc41.noarch

There were two PRs I did in the past related to the qubes-manager exceptions:

But it doesn’t seem to cover you case. Do you keep the qubes-manager constantly open? If yes, do you keep it focused?

Here’s a complete journal.

journalctl.log.gz (2.9 MB)

and here’s the version of the qubes manager:

tomas@dom0:~$ rpm -qf /usr/lib/python3.13/site-packages/qubesmanager
qubes-manager-4.3.22-1.fc41.noarch

As for using disposable qubes - I’m not really using them much, at least not explicitly (e.g. to open e-mail attachments etc.).

log
Aug 04 12:15:35 dom0 systemd-logind[11876]: Lid closed.
Aug 04 12:15:35 dom0 systemd-logind[11876]: Suspending...
Aug 04 12:15:35 dom0 systemd[1]: /usr/lib/systemd/system/qubes-suspend.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Aug 04 12:15:35 dom0 dbus-daemon[14084]: [session uid=1000 pid=14084] Activating service name='org.xfce.Xfconf' requested by ':1.152' (uid=1000 pid=31745 comm="xfconf-query -c xfce4-session -p /general/LockComm")
Aug 04 12:15:35 dom0 dbus-daemon[14084]: [session uid=1000 pid=14084] Successfully activated service 'org.xfce.Xfconf'
Aug 04 12:15:35 dom0 systemd[1]: /usr/lib/systemd/system/qubes-suspend.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Aug 04 12:15:35 dom0 systemd[1]: Starting qubes-suspend.service - Qubes suspend hooks...
Aug 04 12:15:35 dom0 qubesd[11981]: INFO: vm.default-dvm: Removing excess qube(s) from preloaded list because system wants to suspend: 'disp4848, disp3422'
Aug 04 12:15:35 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-178 has been removed.
Aug 04 12:15:35 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-178 has been removed.
Aug 04 12:15:35 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-125 has been removed.
Aug 04 12:15:35 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-125 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-156 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-156 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-177 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-177 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-157 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-157 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-126 has been removed.
Aug 04 12:15:36 dom0 systemd-homed[11875]: block device /sys/devices/virtual/block/dm-126 has been removed.
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp4848' in 'dom0'
Aug 04 12:15:36 dom0 systemd[1]: Starting systemd-hostnamed.service - Hostname Service...
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp3422' in 'dom0'
Aug 04 12:15:36 dom0 systemd[1]: Started systemd-hostnamed.service - Hostname Service.
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp3422: Removing volume root: qubes_dom0/vm-disp3422-root
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp3422: Removing volume private: qubes_dom0/vm-disp3422-private
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp3422: Removing volume volatile: qubes_dom0/vm-disp3422-volatile
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp3422: Removing volume kernel: 7.0.14-1.fc41
Aug 04 12:15:36 dom0 52qubes-pause-vms[31765]: 0
Aug 04 12:15:36 dom0 systemd[1]: Finished qubes-suspend.service - Qubes suspend hooks.
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp4848: Removing volume root: qubes_dom0/vm-disp4848-root
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp4848: Removing volume private: qubes_dom0/vm-disp4848-private
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp4848: Removing volume volatile: qubes_dom0/vm-disp4848-volatile
Aug 04 12:15:36 dom0 qubesd[11981]: INFO: vm.disp4848: Removing volume kernel: 7.0.14-1.fc41
Aug 04 12:15:36 dom0 systemd[1]: Reached target sleep.target - Sleep.
Aug 04 12:15:36 dom0 systemd[1]: Starting systemd-suspend.service - System Suspend...
Aug 04 12:15:36 dom0 systemd-sleep[32036]: This is not recommended, and might result in unexpected behavior, particularly
Aug 04 12:15:36 dom0 systemd-sleep[32036]: in suspend-then-hibernate operations or setups with encrypted home directories.
Aug 04 12:15:36 dom0 systemd-sleep[32036]: Performing sleep operation 'suspend'...
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: The canary thread is apparently starving. Taking action.
Aug 04 12:34:29 dom0 systemd-logind[11876]: Lid opened.
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Demoting known real-time threads.
Aug 04 12:34:29 dom0 systemd-logind[11876]: Lid closed.
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Successfully demoted thread 14103 of process 14090 (/usr/bin/pipewire).
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Successfully demoted thread 14090 of process 14090 (/usr/bin/pipewire).
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Successfully demoted thread 14110 of process 14089 (/usr/bin/wireplumber).
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Successfully demoted thread 14089 of process 14089 (/usr/bin/wireplumber).
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Successfully demoted thread 14096 of process 14088 (/usr/bin/pipewire).
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Successfully demoted thread 14088 of process 14088 (/usr/bin/pipewire).
Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Demoted 6 threads.
Aug 04 12:34:30 dom0 systemd-sleep[32036]: System returned from sleep operation 'suspend'.
Aug 04 12:34:30 dom0 systemd[1]: systemd-suspend.service: Deactivated successfully.
Aug 04 12:34:30 dom0 systemd[1]: Finished systemd-suspend.service - System Suspend.
Aug 04 12:34:30 dom0 systemd[1]: Stopped target sleep.target - Sleep.
Aug 04 12:34:30 dom0 systemd[1]: Reached target suspend.target - Suspend.
Aug 04 12:34:30 dom0 systemd[1]: Stopped target suspend.target - Suspend.
Aug 04 12:34:30 dom0 systemd[1]: Stopping qubes-suspend.service - Qubes suspend hooks...
Aug 04 12:34:30 dom0 systemd-logind[11876]: Operation 'suspend' finished.
Aug 04 12:34:30 dom0 systemd-logind[11876]: Suspending...
Aug 04 12:34:30 dom0 dbus-daemon[14084]: [session uid=1000 pid=14084] Activating service name='org.xfce.Xfconf' requested by ':1.157' (uid=1000 pid=32113 comm="xfconf-query -c xfce4-session -p /general/LockComm")
Aug 04 12:34:30 dom0 dbus-daemon[14084]: [session uid=1000 pid=14084] Successfully activated service 'org.xfce.Xfconf'
Aug 04 12:34:30 dom0 systemd[1]: Starting fprintd.service - Fingerprint Authentication Daemon...
Aug 04 12:34:30 dom0 fprintd[32161]: Failed to install a sleep delay inhibitor: GDBus.Error:org.freedesktop.login1.OperationInProgress: The operation inhibition has been requested for is already running
Aug 04 12:34:30 dom0 systemd[1]: Started fprintd.service - Fingerprint Authentication Daemon.
Aug 04 12:34:30 dom0 upowerd[11878]: Could not acquire inhibitor lock: GDBus.Error:org.freedesktop.login1.OperationInProgress: The operation inhibition has been requested for is already running
Aug 04 12:34:32 dom0 systemd-logind[11876]: Lid opened.
Aug 04 12:34:33 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: secure -> @default: allowed to dom0
Aug 04 12:34:33 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: personal -> @default: allowed to dom0
Aug 04 12:34:33 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: development -> @default: allowed to dom0
Aug 04 12:34:33 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: sys-firewall -> @default: allowed to dom0
Aug 04 12:34:33 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: untrusted -> @default: allowed to dom0
Aug 04 12:34:33 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: sys-usb -> @default: allowed to dom0
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.default-dvm: Received preload event 'start' because system resumed
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.default-dvm: Preloading '2' qube(s)
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7526: Marking preloaded qube
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7526: Creating directory: /var/lib/qubes/appvms/disp7526
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7058: Marking preloaded qube
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7058: Creating directory: /var/lib/qubes/appvms/disp7058
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7526' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp7526' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7058' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp7058' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7526' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7058' in 'dom0'
Aug 04 12:34:33 dom0 52qubes-pause-vms[32118]: 0
Aug 04 12:34:33 dom0 systemd[1]: qubes-suspend.service: Deactivated successfully.
Aug 04 12:34:33 dom0 systemd[1]: Starting qubes-suspend.service - Qubes suspend hooks...
Aug 04 12:34:34 dom0 qubesd[11981]: INFO: vm.default-dvm: Removing excess qube(s) from preloaded list because system wants to suspend: 'disp7526, disp7058'
Aug 04 12:34:34 dom0 qubesd[11981]: INFO: vm.disp7526: Starting qube disp7526
Aug 04 12:34:34 dom0 qubesd[11981]: INFO: vm.disp7058: Starting qube disp7058
Aug 04 12:34:34 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 52qubes-pause-vms[32256]: 0
Aug 04 12:34:34 dom0 systemd[1]: Finished qubes-suspend.service - Qubes suspend hooks.
Aug 04 12:34:34 dom0 systemd[1]: Reached target sleep.target - Sleep.
Aug 04 12:34:34 dom0 systemd[1]: Starting systemd-suspend.service - System Suspend...
Aug 04 12:34:34 dom0 systemd-sleep[32565]: This is not recommended, and might result in unexpected behavior, particularly
Aug 04 12:34:34 dom0 systemd-sleep[32565]: in suspend-then-hibernate operations or setups with encrypted home directories.
Aug 04 12:34:34 dom0 systemd-sleep[32565]: Performing sleep operation 'suspend'...
Aug 04 12:34:36 dom0 systemd-sleep[32565]: System returned from sleep operation 'suspend'.
Aug 04 12:34:36 dom0 systemd[1]: systemd-suspend.service: Deactivated successfully.
Aug 04 12:34:36 dom0 systemd[1]: Finished systemd-suspend.service - System Suspend.
Aug 04 12:34:36 dom0 systemd[1]: Stopped target sleep.target - Sleep.
Aug 04 12:34:36 dom0 systemd[1]: Reached target suspend.target - Suspend.
Aug 04 12:34:36 dom0 systemd-logind[11876]: Operation 'suspend' finished.
Aug 04 12:34:36 dom0 systemd[1]: Stopped target suspend.target - Suspend.
Aug 04 12:34:36 dom0 systemd[1]: Stopping qubes-suspend.service - Qubes suspend hooks...
Aug 04 12:34:38 dom0 qubesd[11981]: INFO: vm.disp7526: Setting Qubes DB info for the qube
Aug 04 12:34:38 dom0 qubesd[11981]: INFO: vm.disp7526: Starting Qubes DB
Aug 04 12:34:38 dom0 qubesd[11981]: INFO: vm.disp7526: Activating qube
Aug 04 12:34:38 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:38 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:38 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:39 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp7058: Setting Qubes DB info for the qube
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp7058: Starting Qubes DB
Aug 04 12:34:40 dom0 qubesd[11981]: WARNING: vm.disp7058: Failed to run qubes.SuspendPostAll: Domain 'disp7058' is paused
Aug 04 12:34:40 dom0 qubesd[11981]: WARNING: vm.disp7526: Failed to run qubes.SuspendPostAll: Domain 'disp7526': qrexec not connected
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp7058: Activating qube
Aug 04 12:34:40 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: development -> @default: allowed to dom0
Aug 04 12:34:40 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: personal -> @default: allowed to dom0
Aug 04 12:34:40 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: sys-firewall -> @default: allowed to dom0
Aug 04 12:34:40 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: secure -> @default: allowed to dom0
Aug 04 12:34:40 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: untrusted -> @default: allowed to dom0
Aug 04 12:34:40 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.GetDate+nanoseconds: sys-usb -> @default: allowed to dom0
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.default-dvm: Received preload event 'start' because system resumed
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.default-dvm: Preloading '2' qube(s)
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp1631: Marking preloaded qube
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp1631: Creating directory: /var/lib/qubes/appvms/disp1631
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp5428: Marking preloaded qube
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp5428: Creating directory: /var/lib/qubes/appvms/disp5428
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp1631' in 'dom0'
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp1631' in 'dom0'
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp5428' in 'dom0'
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp5428' in 'dom0'
Aug 04 12:34:40 dom0 52qubes-pause-vms[32627]: 0
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp1631' in 'dom0'
Aug 04 12:34:40 dom0 systemd[1]: qubes-suspend.service: Deactivated successfully.
Aug 04 12:34:40 dom0 systemd[1]: Stopped qubes-suspend.service - Qubes suspend hooks.
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp5428' in 'dom0'
Aug 04 12:34:41 dom0 qubesd[11981]: INFO: vm.disp5428: Starting qube disp5428
Aug 04 12:34:41 dom0 qubesd[11981]: INFO: vm.disp1631: Starting qube disp1631
Aug 04 12:34:41 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:41 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:41 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:41 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:43 dom0 qubesd[11981]: INFO: vm.disp5428: Setting Qubes DB info for the qube
Aug 04 12:34:43 dom0 qubesd[11981]: INFO: vm.disp5428: Starting Qubes DB
Aug 04 12:34:43 dom0 qubesd[11981]: INFO: vm.disp5428: Activating qube
Aug 04 12:34:43 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:43 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:43 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:43 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:45 dom0 qubesd[11981]: INFO: vm.disp1631: Setting Qubes DB info for the qube
Aug 04 12:34:45 dom0 qubesd[11981]: INFO: vm.disp1631: Starting Qubes DB
Aug 04 12:34:45 dom0 qubesd[11981]: WARNING: protocol error for call b'admin.vm.device.webcam.Attached'+b'' (b'dom0' → b'disp7526') with payload of 0 bytes
Aug 04 12:34:45 dom0 qubesd[11981]: INFO: vm.disp1631: Activating qube
Aug 04 12:34:45 dom0 qubesd[11981]: WARNING: protocol error for call b'admin.vm.device.webcam.Attached'+b'' (b'dom0' → b'disp7058') with payload of 0 bytes
Aug 04 12:34:45 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.Notifications+: disp7526 -> @default: allowed to dom0
Aug 04 12:34:45 dom0 qrexec-policy-daemon[12667]: qrexec: qubes.Notifications+: disp7058 -> @default: allowed to dom0

Lid opened and closed too fast:

Aug 04 12:34:29 dom0 systemd-logind[11876]: Lid opened.
...
Aug 04 12:34:29 dom0 systemd-logind[11876]: Lid closed.
...
Aug 04 12:34:32 dom0 systemd-logind[11876]: Lid opened.

After lid is closed, it suspends:

Aug 04 12:34:29 dom0 rtkit-daemon[13612]: Demoted 6 threads.
Aug 04 12:34:30 dom0 systemd-sleep[32036]: System returned from sleep operation 'suspend'.
Aug 04 12:34:30 dom0 systemd[1]: systemd-suspend.service: Deactivated successfully.
Aug 04 12:34:30 dom0 systemd[1]: Finished systemd-suspend.service - System Suspend.
Aug 04 12:34:30 dom0 systemd[1]: Stopped target sleep.target - Sleep.
Aug 04 12:34:30 dom0 systemd[1]: Reached target suspend.target - Suspend.
Aug 04 12:34:30 dom0 systemd[1]: Stopped target suspend.target - Suspend.
Aug 04 12:34:30 dom0 systemd[1]: Stopping qubes-suspend.service - Qubes suspend hooks...
Aug 04 12:34:30 dom0 systemd-logind[11876]: Operation 'suspend' finished.
Aug 04 12:34:30 dom0 systemd-logind[11876]: Suspending...
Aug 04 12:34:30 dom0 dbus-daemon[14084]: [session uid=1000 pid=14084] Activating service name='org.xfce.Xfconf' requested by ':1.157' (uid=1000 pid=32113 comm="xfconf-query -c xfce4-session -p /general/LockComm")
Aug 04 12:34:30 dom0 dbus-daemon[14084]: [session uid=1000 pid=14084] Successfully activated service 'org.xfce.Xfconf'
Aug 04 12:34:30 dom0 systemd[1]: Starting fprintd.service - Fingerprint Authentication Daemon...
Aug 04 12:34:30 dom0 fprintd[32161]: Failed to install a sleep delay inhibitor: GDBus.Error:org.freedesktop.login1.OperationInProgress: The operation inhibition has been requested for is already running
Aug 04 12:34:30 dom0 systemd[1]: Started fprintd.service - Fingerprint Authentication Daemon.
Aug 04 12:34:30 dom0 upowerd[11878]: Could not acquire inhibitor lock: GDBus.Error:org.freedesktop.login1.OperationInProgress: The operation inhibition has been requested for is already running

Then lid is opened and system resumes:

Aug 04 12:34:32 dom0 systemd-logind[11876]: Lid opened.
...
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.default-dvm: Received preload event 'start' because system resumed
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.default-dvm: Preloading '2' qube(s)
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7526: Marking preloaded qube
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7526: Creating directory: /var/lib/qubes/appvms/disp7526
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7058: Marking preloaded qube
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: vm.disp7058: Creating directory: /var/lib/qubes/appvms/disp7058
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7526' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp7526' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7058' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Removing appmenus for 'disp7058' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7526' in 'dom0'
Aug 04 12:34:33 dom0 qubesd[11981]: INFO: Updating appmenus for 'disp7058' in 'dom0'

But suspend is started again, you see the disposables are removed from the preload list because system wants to suspend, but the disposables continue their startup:

Aug 04 12:34:33 dom0 52qubes-pause-vms[32118]: 0
Aug 04 12:34:33 dom0 systemd[1]: qubes-suspend.service: Deactivated successfully.
Aug 04 12:34:33 dom0 systemd[1]: Starting qubes-suspend.service - Qubes suspend hooks...
Aug 04 12:34:34 dom0 qubesd[11981]: INFO: vm.default-dvm: Removing excess qube(s) from preloaded list because system wants to suspend: 'disp7526, disp7058'
Aug 04 12:34:34 dom0 qubesd[11981]: INFO: vm.disp7526: Starting qube disp7526
Aug 04 12:34:34 dom0 qubesd[11981]: INFO: vm.disp7058: Starting qube disp7058
Aug 04 12:34:34 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:34 dom0 52qubes-pause-vms[32256]: 0
Aug 04 12:34:34 dom0 systemd[1]: Finished qubes-suspend.service - Qubes suspend hooks.
Aug 04 12:34:34 dom0 systemd[1]: Reached target sleep.target - Sleep.

Suspend is started again:

Aug 04 12:34:34 dom0 systemd[1]: Starting systemd-suspend.service - System Suspend...
Aug 04 12:34:34 dom0 systemd-sleep[32565]: This is not recommended, and might result in unexpected behavior, particularly
Aug 04 12:34:34 dom0 systemd-sleep[32565]: in suspend-then-hibernate operations or setups with encrypted home directories.
Aug 04 12:34:34 dom0 systemd-sleep[32565]: Performing sleep operation 'suspend'...
Aug 04 12:34:36 dom0 systemd-sleep[32565]: System returned from sleep operation 'suspend'.
Aug 04 12:34:36 dom0 systemd[1]: systemd-suspend.service: Deactivated successfully.
Aug 04 12:34:36 dom0 systemd[1]: Finished systemd-suspend.service - System Suspend.
Aug 04 12:34:36 dom0 systemd[1]: Stopped target sleep.target - Sleep.
Aug 04 12:34:36 dom0 systemd[1]: Reached target suspend.target - Suspend.
Aug 04 12:34:36 dom0 systemd-logind[11876]: Operation 'suspend' finished.
Aug 04 12:34:36 dom0 systemd[1]: Stopped target suspend.target - Suspend.
Aug 04 12:34:36 dom0 systemd[1]: Stopping qubes-suspend.service - Qubes suspend hooks...

Disposables continue their startup:

Aug 04 12:34:38 dom0 qubesd[11981]: INFO: vm.disp7526: Setting Qubes DB info for the qube
Aug 04 12:34:38 dom0 qubesd[11981]: INFO: vm.disp7526: Starting Qubes DB
Aug 04 12:34:38 dom0 qubesd[11981]: INFO: vm.disp7526: Activating qube
Aug 04 12:34:38 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:38 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:38 dom0 dmeventd[11129]: No longer monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:39 dom0 dmeventd[11129]: Monitoring thin pool qubes_dom0-vm--pool-tpool.
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp7058: Setting Qubes DB info for the qube
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp7058: Starting Qubes DB

The internal API internal.SuspendPost is called, but it tries to resumt the previously preloaded disposables, this service should never have been called for those qubes, but the error is earlier:

Aug 04 12:34:40 dom0 qubesd[11981]: WARNING: vm.disp7058: Failed to run qubes.SuspendPostAll: Domain 'disp7058' is paused
Aug 04 12:34:40 dom0 qubesd[11981]: WARNING: vm.disp7526: Failed to run qubes.SuspendPostAll: Domain 'disp7526': qrexec not connected
Aug 04 12:34:40 dom0 qubesd[11981]: INFO: vm.disp7058: Activating qube

I don’t know what to make of this right now.

  • Do you have a custom suspend script?
  • Do you have configured suspend in Xfce different than the default? If yes, could you please share?
  • Do you know what triggers the fast lid open close open?

I think I know what happens. The domains are marked as preload, suspend is called, the removal of the domains is called, but the domains are not running, and it skips cleanup…

I don’t like requiring the force, but I remember that without that, it cause a lot of issues only caught by OpenQA. It depends on the circumstance in which cleanup() is called, but I think that for this “removal of excess”, it is safe enough.

Can you try changing this line:

To

                    asyncio.ensure_future(dispvm.cleanup(force=True))

I don’t have any custom suspend scripts, and I don’t remember messing with this in some way. Same for suspend config in xfce. I might have enabled/disabled a presentation mode, but that’s about it. I think it’s pretty much a “clean” install.

As for the fast lid open/close - well, it’s a laptop. So I guess I might have actually opened/closed the lid for some reason. I might have been investigating this issue, for example, trying to reproduce it by closing/opening the lid quickly etc.

Do you know how to find qubesd files to edit?

vim /usr/lib/python3.*/site-packages/qubes/vm/mix/dvmtemplate.py

Then after editing the file with the force=True as above, systemctl restart qubesd. And do you normal suspend procedure. Please report in a few days if the issue still happens.

I’ve modified the force=True parameter and rebooted the laptop, to start from a clean state. Will watch if the issue re-appears in the next couple days.

Any feedback on this?