Wait for user session for preloaded disposables

With the GUI agent patch, it can start before the GUI daemon connects,
allowing the user session to complete. Wait both services to guarantee
no enabled user or system service tries to start after the preload is
used.

Requires: QubesOS/qubes-gui-agent-linux#251
Fixes: QubesOS/qubes-issues#9940
For: QubesOS/qubes-issues#1512

Author: ben-grande

qubes/tests/api_admin.py

@@ -3996,6 +3996,7 @@ def test_643_vm_create_disposable_preload_autostart(
         )
         self.vm.features["qrexec"] = "1"
         self.vm.features["supported-rpc.qubes.WaitForRunningSystem"] = "1"
+        self.vm.features["supported-rpc.qubes.WaitForSession"] = "1"
         self.vm.features["preload-dispvm-max"] = "1"
         for _ in range(10):
             if len(self.vm.get_feat_preload()) == 1:

qubes/tests/app.py

@@ -704,6 +704,7 @@ def setUp(self):
         self.template.features["supported-rpc.qubes.WaitForRunningSystem"] = (
             True
         )
+        self.template.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm = self.app.add_new_vm(
             "AppVM",
             name="test-dvm",

qubes/tests/integ/backup.py

@@ -188,6 +188,7 @@ def create_backup_vms(self, pool=None):
         self.loop.run_until_complete(testvm5.create_on_disk(pool=pool))
         testvm5.features["qrexec"] = True
         testvm5.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        testvm5.features["supported-rpc.qubes.WaitForSession"] = True
         testvm5.features["preload-dispvm-max"] = 0
         testvm5.features["preload-dispvm"] = ""
         vms.append(testvm5)

qubes/tests/vm/dispvm.py

@@ -155,6 +155,7 @@ def test_000_from_appvm_preload_reject_max(self, mock_storage):
         self.appvm.template_for_dispvms = True
         orig_getitem = self.app.domains.__getitem__
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm.features["preload-dispvm-max"] = "0"
         with mock.patch.object(
             self.app, "domains", wraps=self.app.domains
@@ -186,6 +187,7 @@ def test_000_from_appvm_preload_use(
         self.appvm.template_for_dispvms = True
 
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm.features["preload-dispvm-max"] = "1"
         orig_getitem = self.app.domains.__getitem__
         with mock.patch.object(
@@ -250,6 +252,7 @@ def test_000_from_appvm_preload_fill_gap(
         mock_start.side_effect = self.mock_coro
         self.appvm.template_for_dispvms = True
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         orig_getitem = self.app.domains.__getitem__
         with mock.patch("qubes.events.Emitter.fire_event_async") as mock_events:
             self.appvm.features["preload-dispvm-max"] = "1"
@@ -293,6 +296,7 @@ def test_000_from_appvm_preload_fill_gap(
     def test_000_get_preload_max(self):
         self.assertEqual(qubes.vm.dispvm.get_preload_max(self.appvm), None)
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm.features["preload-dispvm-max"] = 1
         self.assertEqual(qubes.vm.dispvm.get_preload_max(self.appvm), 1)
         self.assertEqual(qubes.vm.dispvm.get_preload_max(self.adminvm), None)
@@ -309,9 +313,11 @@ def test_000_get_preload_templates(self):
         self.assertEqual(get_preload_templates(self.app), [])
 
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm_alt.features["supported-rpc.qubes.WaitForRunningSystem"] = (
             True
         )
+        self.appvm_alt.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm.features["preload-dispvm-max"] = 1
         self.appvm_alt.features["preload-dispvm-max"] = 0
         self.assertEqual(get_preload_templates(self.app), [self.appvm])

qubes/tests/vm/mix/dvmtemplate.py

@@ -84,6 +84,7 @@ def setUp(self):
         self.appvm.features["qrexec"] = True
         self.appvm.features["gui"] = False
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.app.domains[self.appvm.name] = self.appvm
         self.app.domains[self.appvm] = self.appvm
         self.app.default_dispvm = self.appvm
@@ -140,9 +141,13 @@ def test_010_dvm_preload_get_max(self):
         self.appvm.features["qrexec"] = True
         self.appvm.features["gui"] = False
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = False
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = False
         with self.assertRaises(qubes.exc.QubesValueError):
             self.appvm.features["preload-dispvm-max"] = "1"
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        with self.assertRaises(qubes.exc.QubesValueError):
+            self.appvm.features["preload-dispvm-max"] = "1"
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm.features["preload-dispvm-max"] = "1"
         cases_invalid = ["a", "-1", "1 1"]
         for value in cases_invalid:
@@ -435,5 +440,6 @@ def test_040_dvm_preload_set_template_for_dispvms(
     def test_100_get_preload_templates(self):
         print(qubes.vm.dispvm.get_preload_templates(self.app))
         self.appvm.features["supported-rpc.qubes.WaitForRunningSystem"] = True
+        self.appvm.features["supported-rpc.qubes.WaitForSession"] = True
         self.appvm.features["preload-dispvm-max"] = 1
         self.assertEqual(qubes.vm.dispvm.get_preload_max(self.appvm), 1)

qubes/vm/dispvm.py

@@ -422,27 +422,16 @@ def on_domain_loaded(self, event) -> None:
         # pylint: disable=unused-argument
         assert self.template
 
-    @qubes.events.handler("domain-start")
-    async def on_domain_started_dispvm(
-        self,
-        event,
-        **kwargs,
-    ):
-        # pylint: disable=unused-argument
+    async def wait_operational_preload(
+        self, rpc: str, service: str, timeout: int | float
+    ) -> None:
         """
-        When starting a qube, await for basic services to be started on
-        preloaded disposables and interrupts the domain if the qube has not
-        been requested yet.
+        Await for preloaded disposable to become fully operational.
 
-        :param str event: Event which was fired.
+        :param str rpc: Pretty RPC service name.
+        :param str service: Full command-line.
+        :param int|float timeout: Fail after timeout is reached.
         """
-        if not self.is_preload:
-            return
-        timeout = self.qrexec_timeout
-        # https://github.com/QubesOS/qubes-issues/issues/9964
-        rpc = "qubes.WaitForRunningSystem"
-        path = "/run/qubes-rpc:/usr/local/etc/qubes-rpc:/etc/qubes-rpc"
-        service = '$(PATH="' + path + '" command -v ' + rpc + ")"
         try:
             self.log.info(
                 "Preload startup waiting '%s' with '%d' seconds timeout",
@@ -457,18 +446,68 @@ async def on_domain_started_dispvm(
                 ),
                 timeout=timeout,
             )
+            self.log.info("Preload startup completed '%s'", rpc)
         except asyncio.TimeoutError:
+            if rpc == "qubes.WaitForSession":
+                debug_msg = "systemd-analyze --user blame"
+            else:
+                debug_msg = "systemd-analyze blame"
             raise qubes.exc.QubesException(
                 "Timed out call to '%s' after '%d' seconds during preload "
-                "startup" % (rpc, timeout)
+                "startup. To debug, run the following on a new disposable of "
+                "'%s': %s" % (rpc, timeout, self.template, debug_msg)
             )
         except (subprocess.CalledProcessError, qubes.exc.QubesException):
+            if rpc == "qubes.WaitForSession":
+                debug_msg = "systemctl --user --failed"
+            else:
+                debug_msg = "systemctl --failed"
             raise qubes.exc.QubesException(
-                "Error on call to '%s' during preload startup. To debug, run "
-                "the following on a new disposable of '%s': systemctl "
-                "--failed" % (rpc, self.template)
+                "Error on call to '%s' during preload startup. To debug, "
+                "run the following on a new disposable of '%s': %s"
+                % (rpc, self.template, debug_msg)
             )
 
+    @qubes.events.handler("domain-start")
+    async def on_domain_started_dispvm(
+        self,
+        event,
+        **kwargs,
+    ):
+        # pylint: disable=unused-argument
+        """
+        When starting a qube, await for basic services to be started on
+        preloaded disposables and interrupts the domain if the qube has not
+        been requested yet.
+
+        :param str event: Event which was fired.
+        """
+        if not self.is_preload:
+            return
+        timeout = self.qrexec_timeout
+        # https://github.com/QubesOS/qubes-issues/issues/9964
+        path = "/run/qubes-rpc:/usr/local/etc/qubes-rpc:/etc/qubes-rpc"
+        rpcs = ["qubes.WaitForRunningSystem"]
+        if self.features.check_with_template(
+            "supported-feature.late-gui-daemon", False
+        ):
+            rpcs.append("qubes.WaitForSession")
+        try:
+            async with asyncio.TaskGroup() as task_group:
+                for rpc in rpcs:
+                    service = '$(PATH="' + path + '" command -v ' + rpc + ")"
+                    task_group.create_task(
+                        self.wait_operational_preload(rpc, service, timeout)
+                    )
+        except ExceptionGroup as e:
+            # Show detailed exception in desktop notification.
+            wanted_ex_group, _ = e.split(qubes.exc.QubesException)
+            if wanted_ex_group:
+                messages = [
+                    "\n" + str(exc) for exc in wanted_ex_group.exceptions
+                ]
+                raise qubes.exc.QubesException("\n".join(messages))
+            raise
         if not self.preload_requested:
             await self.pause()
         self.log.info("Preloading finished")

qubes/vm/mix/dvmtemplate.py

@@ -19,7 +19,7 @@
 # with this program; if not, see <http://www.gnu.org/licenses/>.
 
 import asyncio
-from typing import Optional, Union, Iterator
+from typing import Optional, Union, Iterator, Tuple
 
 import qubes.config
 import qubes.events
@@ -180,10 +180,11 @@ def on_feature_pre_set_preload_dispvm_max(
         if not self.features.check_with_template("qrexec", None):
             raise qubes.exc.QubesValueError("Qube does not support qrexec")
 
-        service = "qubes.WaitForRunningSystem"
-        if not self.supports_preload():
+        supported, missing_services = self.supports_preload()
+        if not supported:
             raise qubes.exc.QubesValueError(
-                "Qube does not support the RPC '%s'" % service
+                "Qube does not support the RPC(s) '%s'"
+                % ", ".join(missing_services)
             )
 
         value = value or "0"
@@ -445,11 +446,12 @@ async def on_domain_preload_dispvm_used(
         if delay:
             event_log += " with a delay of %s second(s)" % f"{delay:.1f}"
         self.log.info(event_log)
-        service = "qubes.WaitForRunningSystem"
-        if not self.supports_preload():
+
+        supported, missing_services = self.supports_preload()
+        if not supported:
             raise qubes.exc.QubesValueError(
-                "Qube does not support the RPC '%s' but tried to preload, "
-                "check if template is outdated" % service
+                "Qube does not support the RPC(s) '%s' but tried to preload, "
+                "check if template is outdated" % ", ".join(missing_services)
             )
         if delay:
             await asyncio.sleep(delay)
@@ -672,15 +674,21 @@ def remove_preload_excess(
                     dispvm = self.app.domains[unwanted_disp]
                     asyncio.ensure_future(dispvm.cleanup())
 
-    def supports_preload(self) -> bool:
+    def supports_preload(self) -> Tuple[bool, list]:
         """
-        Check if the necessary RPC is supported.
+        Check if the necessary RPCs are supported.
 
-        :rtype: bool
+        The first returned value indicates success while the second value is
+        non empty and contains the missing services if they are not supported.
+
+        :rtype: (bool, list)
         """
         assert isinstance(self, qubes.vm.BaseVM)
-        service = "qubes.WaitForRunningSystem"
-        supported_service = "supported-rpc." + service
-        if self.features.check_with_template(supported_service, False):
-            return True
-        return False
+        supported = True
+        missing_services = []
+        for service in ["qubes.WaitForRunningSystem", "qubes.WaitForSession"]:
+            feature = "supported-rpc." + service
+            if not self.features.check_with_template(feature, False):
+                missing_services.append(service)
+                supported = False
+        return (supported, missing_services)