Late GUID for preloaded disposables

[ben-grande]

• Autostarted applications don't show when preloading; and
• Preloaded qubes paused before the session will have a working GUI when
  the session starts.

For: QubesOS/qubes-issues#1512
For: QubesOS/qubes-issues#9940
For: QubesOS/qubes-issues#9907

[ben-grande]

Before this is merged, let me know to update the documentation of the manpage and the DispVM class accordingly. Maybe I will merge this PR:

• with Document preloaded disposables #354

[ben-grande]

This is working because failing qubes.WaitForSession was just logging a warning, I changed it to raise QubesException because it is more correct.

https://github.com/QubesOS/qubes-core-admin/blob/b1d178670abea07cc1d3f51243fd3d18fb49d707/qubes/vm/dispvm.py#L354

https://github.com/QubesOS/qubes-core-admin/compare/d53d9604b026fa0fd7e5d7c4015996618f4651a9..b1d178670abea07cc1d3f51243fd3d18fb49d707

But now, qubes.WaitForSession can't be called there, only qubes.WaitForRunningSystem, which is okay even for the GUI qube as it doesn't connect before being used due to this PR.

Adding a check for qubes.WaitForSession after being marked as used doesn't make sense I believe, because, well, it adds a test but won't help with anything...

---

Note to self:

This requires changes in core-admin:

• no qubes.WaitForSession
• change domain-pre-unpaused to domain-unpaused

[ben-grande]

I haven't checked if there is any impact of a super late connection, such as a preload that was paused for some hours and them it is unpaused and the GUID will try to connect, will have to check if the client responds.

[ben-grande]

Should I use force_stubdom=True? I haven't experimented with HVMs for this use case.

[ben-grande]

@marmarek

[marmarek]

No, force_stubdomain is only a debugging feature

[ben-grande]

Rebased on top of:

• Document preloaded disposables #354

[marmarek]

There is a merge conflict now...

[marmarek]

Oh, I see a bunch of related exceptions in .xsession-errors log:

/usr/lib/python3.13/site-packages/qubesadmin/tools/qvm_start_daemon.py:821> exception=TypeError('expected str, bytes or os.PathLike object, not int')>
Traceback (most recent call last):
  File "/usr/lib/python3.13/site-packages/qubesadmin/tools/qvm_start_daemon.py", line 840, in start_audio
    await self.start_audio_for_vm(vm)
  File "/usr/lib/python3.13/site-packages/qubesadmin/tools/qvm_start_daemon.py", line 793, in start_audio_for_vm
    await asyncio.create_subprocess_exec(*pacat_cmd)
  File "/usr/lib64/python3.13/asyncio/subprocess.py", line 224, in create_subprocess_exec
    transport, protocol = await loop.subprocess_exec(
                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<3 lines>...
        stderr=stderr, **kwds)
        ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/asyncio/base_events.py", line 1788, in subprocess_exec
    transport = await self._make_subprocess_transport(
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        protocol, popen_args, False, stdin, stdout, stderr,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        bufsize, **kwargs)
        ^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/asyncio/unix_events.py", line 213, in _make_subprocess_transport
    transp = _UnixSubprocessTransport(self, protocol, args, shell,
                                    stdin, stdout, stderr, bufsize,
                                    waiter=waiter, extra=extra,
                                    **kwargs)
  File "/usr/lib64/python3.13/asyncio/base_subprocess.py", line 39, in __init__
    self._start(args=args, shell=shell, stdin=stdin, stdout=stdout,
    ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                stderr=stderr, bufsize=bufsize, **kwargs)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/asyncio/unix_events.py", line 855, in _start
    self._proc = subprocess.Popen(
                 ~~~~~~~~~~~~~~~~^
        args, shell=shell, stdin=stdin, stdout=stdout, stderr=stderr,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        universal_newlines=False, bufsize=bufsize, **kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/subprocess.py", line 1039, in __init__
    self._execute_child(args, executable, preexec_fn, close_fds,
    ~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                        pass_fds, cwd, env,
                        ^^^^^^^^^^^^^^^^^^^
    ...<5 lines>...
                        gid, gids, uid, umask,
                        ^^^^^^^^^^^^^^^^^^^^^^
                        start_new_session, process_group)
                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/subprocess.py", line 1854, in _execute_child
    self._posix_spawn(args, executable, env, restore_signals, close_fds,
    ~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
                      p2cread, p2cwrite,
                      ^^^^^^^^^^^^^^^^^^
                      c2pread, c2pwrite,
                      ^^^^^^^^^^^^^^^^^^
                      errread, errwrite)
                      ^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/subprocess.py", line 1798, in _posix_spawn
    self.pid = os.posix_spawn(executable, args, env, **kwargs)
               ~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TypeError: expected str, bytes or os.PathLike object, not int

[marmarek]

I fixed preserving types, and now xid is actually int...

[marmarek]

#367

[marmarek]

I'm merging #367 now, and it will require this PR to be rebased (there is a small conflict).

[ben-grande]

• TC_20_DispVM_fedora-42-xfce: test_015_dvm_run_preload_race_more (failure)
  ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^... AssertionError: False is not true

I was worried a bit but the error is this:

Traceback (most recent call last):
  File "/usr/bin/qvm-run", line 5, in <module>
    sys.exit(main())
             ~~~~^^
  File "/usr/lib/python3.13/site-packages/qubesadmin/tools/qvm_run.py", line 288, in main
    sys.stderr.flush()
    ~~~~~~~~~~~~~~~~^^
BlockingIOError: [Errno 11] write could not complete without blocking

So I will just add --no-color-output --no-color-stderr to reduce the cases where the issue can happen.

---

Now the preload-dispvm-completed feature not being registered in the test events:

Traceback (most recent call last):
  File "/usr/lib64/python3.13/contextlib.py", line 85, in inner
    return func(*args, **kwds)
  File "/usr/lib/python3.13/site-packages/qubes/tests/integ/dispvm.py", line 429, in test_013_dvm_run_preload_gui
    self.loop.run_until_complete(self._test_013_dvm_run_preload_gui())
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/asyncio/base_events.py", line 719, in run_until_complete
    return future.result()
           ~~~~~~~~~~~~~^^
  File "/usr/lib/python3.13/site-packages/qubes/tests/integ/dispvm.py", line 437, in _test_013_dvm_run_preload_gui
    await self.run_preload()
  File "/usr/lib/python3.13/site-packages/qubes/tests/integ/dispvm.py", line 352, in run_preload
    self.assertTrue(
    ~~~~~~~~~~~~~~~^
        self._test_event_was_handled(
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
            dispvm_name, "domain-feature-set:preload-dispvm-completed"
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
        )
        ^
    )
    ^
AssertionError: None is not true

diff --git a/qubes/tests/integ/dispvm.py b/qubes/tests/integ/dispvm.py
index f1f6fa23..60de4e31 100644
--- a/qubes/tests/integ/dispvm.py
+++ b/qubes/tests/integ/dispvm.py
@@ -267,7 +267,11 @@ class TC_20_DispVMMixin(object):
         preload_unfinished = preload_dispvm
         for _ in range(60):
             for qube in preload_unfinished.copy():
-                if self.app.domains[qube].preload_complete.is_set():
+                qo = self.app.domains[qube]
+                if qo.preload_complete.is_set():
+                    logger.info("preload completed for '%s'", qube)
+                    feat = qo.features.get("preload-dispvm-completed")
+                    logger.info("preload completed feature '%s'", feat)
                     preload_unfinished.remove(qube)
                     continue
             if not preload_unfinished:

...
INFO: wait_preload: start
INFO: wait_preload: preload completed for 'disp8751'
INFO: wait_preload: preload completed feature '1'
INFO: wait_preload: end
...

======================================================================
FAIL: qubes.tests.integ.dispvm/TC_20_DispVM_debian-12-xfce/test_013_dvm_run_preload_gui (assert_type=True, qube='disp8751', event='domain-feature-set:preload-dispvm-completed', test=True)
  Test preloading with GUI feature enabled and use after
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/user/qubes-core-admin/qubes/tests/integ/dispvm.py", line 375, in run_preload
    self.assertTrue(event_result)
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^
AssertionError: None is not true

----------------------------------------------------------------------
Ran 1 test in 12.653s

FAILED (failures=1)

The feature is set, but the event handler hasn't registered it yet?

[ben-grande]

If I delete the feature on use_preload() in vm/dispvm.py and add handler for domian-feature-delete:preload-dispvm-completed in the run_preload() in tests/integ/dispvm.py, the delete check pass but the set check still doesn't pass.

[marmarek]

The feature is set, but the event handler hasn't registered it yet?

Maybe the handler is not registered on the correct object? I guess you can add some logging when adding handlers and see which objects get them.

[ben-grande]

Maybe the handler is not registered on the correct object? I guess you can add some logging when adding handlers and see which objects get them.

Correct, it is not registered at all... will investigate why.

run_preload: start
run_preload_proc: start
_test_event_handler: disp5557[domain-feature-set:preload-dispvm-in-progress]=True
_test_event_handler: disp5557[domain-feature-delete:internal]=True
_test_event_handler: disp5557[domain-feature-delete:preload-dispvm-in-progress]=True
_test_event_handler: disp5557[domain-unpaused]=True
_test_event_handler: test-inst-dvm[domain-preload-dispvm-used]=True
run_preload_proc: end
_test_event_was_handled: disp5557[domain-paused]='None'
_test_event_was_handled: test-inst-dvm[domain-preload-dispvm-autostart]='None'
_test_event_was_handled: test-inst-dvm[domain-preload-dispvm-start]='None'
_test_event_was_handled: test-inst-dvm[domain-preload-dispvm-used]='True'
_test_event_was_handled: disp5557[domain-feature-set:preload-dispvm-in-progress]='True'
_test_event_was_handled: disp5557[domain-feature-delete:preload-dispvm-in-progress]='True'
_test_event_was_handled: disp5557[domain-feature-set:preload-dispvm-completed]='None'
_test_event_was_handled: disp5557[domain-feature-delete:internal]='True'
run_preload: end

[ben-grande]

Probably related to the wait_completion, the qube should also have been paused and unpaused, but because adding the event only happens after the qube has finished preloading, it is not gathering the correct result.