Switch autostart event in favor of only start

The autostart made a refresh, which cleaned all preloaded disposables,
served to:

- Invalidate previous incomplete remnants
- Get fresh ones after a change was made to a template in chain

Both of these issues were handled, "domain-load" of the disposable
template invalidates incomplete ones while "domain-shutdown" of a
template in chain triggers a refresh.

For: QubesOS/qubes-issues#1512

Author: ben-grande

linux/aux-tools/preload-dispvm

@@ -54,7 +54,7 @@ async def main():
                 maximum = get_preload_max(qube)
                 msg = f"{qube}:{maximum}"
             print(repr(msg))
-            exec_args = qube.qubesd_call, qube.name, method, "preload-autostart"
+            exec_args = qube.qubesd_call, qube.name, method, "preload"
             future = loop.run_in_executor(executor, *exec_args)
             tasks.append(future)
         await asyncio.gather(*tasks)

qubes/api/admin.py

@@ -1308,13 +1308,13 @@ async def _vm_create(
     @qubes.api.method("admin.vm.CreateDisposable", scope="global", write=True)
     async def create_disposable(self, untrusted_payload):
         """
-        Create a disposable. If the RPC argument is ``preload-autostart``,
+        Create a disposable. If the RPC argument is ``preload``,
         cleanse the preload list and start preloading fresh disposables.
         """
-        self.enforce(self.arg in [None, "", "preload-autostart"])
-        preload_autostart = False
-        if self.arg == "preload-autostart":
-            preload_autostart = True
+        self.enforce(self.arg in [None, "", "preload"])
+        preload = False
+        if self.arg == "preload":
+            preload = True
         if untrusted_payload not in (b"", b"uuid"):
             raise qubes.exc.QubesValueError(
                 "Invalid payload for admin.vm.CreateDisposable: "
@@ -1327,8 +1327,10 @@ async def create_disposable(self, untrusted_payload):
             appvm = self.dest
 
         self.fire_event_for_permission(dispvm_template=appvm)
-        if preload_autostart:
-            await appvm.fire_event_async("domain-preload-dispvm-autostart")
+        if preload:
+            await appvm.fire_event_async(
+                "domain-preload-dispvm-start", reason="autostart was requested"
+            )
             return
         dispvm = await qubes.vm.dispvm.DispVM.from_appvm(appvm)
         # TODO: move this to extension (in race-free fashion, better than here)

qubes/api/internal.py

@@ -413,5 +413,7 @@ async def suspend_post(self):
         preload_templates = qubes.vm.dispvm.get_preload_templates(self.app)
         for qube in preload_templates:
             asyncio.ensure_future(
-                qube.fire_event_async("domain-preload-dispvm-autostart")
+                qube.fire_event_async(
+                    "domain-preload-dispvm-start", reason="system resumed"
+                )
             )

qubes/tests/api_admin.py

@@ -3992,7 +3992,7 @@ def test_643_vm_create_disposable_preload_autostart(
         self.vm.template_for_dispvms = True
         self.app.default_dispvm = self.vm
         self.vm.add_handler(
-            "domain-preload-dispvm-autostart", self._test_event_handler
+            "domain-preload-dispvm-start", self._test_event_handler
         )
         self.vm.features["qrexec"] = "1"
         self.vm.features["supported-rpc.qubes.WaitForRunningSystem"] = "1"
@@ -4005,27 +4005,23 @@ def test_643_vm_create_disposable_preload_autostart(
             self.fail("didn't preload in time")
         old_preload = self.vm.get_feat_preload()
         retval = self.call_mgmt_func(
-            b"admin.vm.CreateDisposable", b"dom0", arg=b"preload-autostart"
+            b"admin.vm.CreateDisposable", b"dom0", arg=b"preload"
         )
         self.assertTrue(
             self._test_event_was_handled(
-                self.vm.name, "domain-preload-dispvm-autostart"
+                self.vm.name, "domain-preload-dispvm-start"
             )
         )
-        for _ in range(10):
-            if (
-                old_preload != self.vm.get_feat_preload()
-                and self.vm.get_feat_preload() != []
-            ):
-                break
-            self.loop.run_until_complete(asyncio.sleep(1))
-        else:
-            self.fail("didn't preload again in time")
-        dispvm_preload = self.vm.get_feat_preload()
-        self.assertEqual(len(dispvm_preload), 1)
+        self.call_mgmt_func(
+            b"admin.vm.CreateDisposable", b"dom0", arg=b"preload"
+        )
+        self.assertEqual(1, mock_storage_create.call_count)
+        new_preload = self.vm.get_feat_preload()
+        self.assertEqual(len(old_preload), 1)
+        self.assertEqual(len(new_preload), 1)
+        self.assertEqual(old_preload, new_preload)
         self.assertIsNone(retval)
-        self.assertEqual(2, mock_storage_create.call_count)
-        self.assertEqual(2, mock_dispvm_start.call_count)
+        self.assertEqual(1, mock_dispvm_start.call_count)
         self.assertTrue(self.app.save.called)
 
     def test_650_vm_device_set_mode_required(self):

qubes/tests/integ/dispvm.py

@@ -262,6 +262,20 @@ def tearDown(self):  # pylint: disable=invalid-name
         super(TC_20_DispVMMixin, self).tearDown()
         logger.info("end")
 
+    def _run_cmd_and_log_output(self, qube, cmd, user="root", timeout=30):
+        try:
+            stdout, _ = self.loop.run_until_complete(
+                asyncio.wait_for(
+                    qube.run_for_stdio(
+                        cmd, user=user, stderr=subprocess.STDOUT
+                    ),
+                    timeout=timeout,
+                )
+            )
+        except subprocess.CalledProcessError as e:
+            stdout = getattr(e, "stdout", str(e))
+        logger.critical("{}: {}: {}".format(qube.name, cmd, stdout))
+
     def _test_event_handler(
         self, vm, event, *args, **kwargs
     ):  # pylint: disable=unused-argument
@@ -285,7 +299,6 @@ def _test_event_was_handled(self, vm, event):
     def _register_handlers(self, vm):  # pylint: disable=unused-argument
         events = [
             # appvm
-            "domain-preload-dispvm-autostart",
             "domain-preload-dispvm-start",
             "domain-preload-dispvm-used",
             # dispvm
@@ -304,11 +317,12 @@ def _register_handlers(self, vm):  # pylint: disable=unused-argument
     def _on_domain_add(self, app, event, vm):  # pylint: disable=unused-argument
         self._register_handlers(vm)
 
-    async def cleanup_preload_run(self, qube):
+    async def cleanup_preload_run(self, qube, down_to=0):
         old_preload = qube.features.get("preload-dispvm", "")
         old_preload = old_preload.split(" ") if old_preload else []
         if not old_preload:
             return
+        old_preload = old_preload[:down_to]
         logger.info(
             "cleaning up preloaded disposables: %s:%s", qube.name, old_preload
         )
@@ -333,7 +347,9 @@ def cleanup_preload(self):
                 self.disp_base_alt,
             ]:
                 continue
-            logger.info("removing preloaded disposables: '%s'", qube.name)
+            logger.info(
+                "removing preloaded disposables configured in: '%s'", qube.name
+            )
             target = qube
             if qube.klass == "AdminVM" and default_dispvm:
                 target = default_dispvm
@@ -453,7 +469,6 @@ async def run_preload(self):
         stdout = await self.run_preload_proc()
         self.assertEqual(stdout, dispvm_name)
         test_cases = [
-            (False, appvm.name, "domain-preload-dispvm-autostart", True),
             (False, appvm.name, "domain-preload-dispvm-start", True),
             (True, appvm.name, "domain-preload-dispvm-used", True),
             (
@@ -637,15 +652,12 @@ async def _test_016_preload_race_less(self):
         logger.info("end")
 
     def test_017_preload_autostart(self):
-        """The script triggers the API call
-        'admin.vm.CreateDisposable+preload-autostart' which fires the event
-        'domain-preload-dispvm-autostart', clearing the current preload list
-        and filling with new ones."""
+        """The script triggers the API call 'admin.vm.CreateDisposable+preload'
+        which is responsible for bootstrapping."""
         logger.info("start")
         self.app.default_dispvm = self.disp_base
 
-        preload_max = 1
-        logger.info("no refresh to be made")
+        logger.info("must not change as max is 0")
         proc = self.loop.run_until_complete(
             asyncio.create_subprocess_exec("/usr/lib/qubes/preload-dispvm")
         )
@@ -654,39 +666,70 @@ def test_017_preload_autostart(self):
         )
         self.assertEqual(self.disp_base.get_feat_preload(), [])
 
-        logger.info("refresh to be made")
+        preload_max = 1
+        logger.info("must not change existing preloaded disposables")
         self.disp_base.features["preload-dispvm-max"] = str(preload_max)
         self.loop.run_until_complete(self.wait_preload(preload_max))
         old_preload = self.disp_base.get_feat_preload()
         proc = self.loop.run_until_complete(
             asyncio.create_subprocess_exec("/usr/lib/qubes/preload-dispvm")
         )
-        self.loop.run_until_complete(asyncio.wait_for(proc.wait(), timeout=40))
+        self.loop.run_until_complete(asyncio.wait_for(proc.wait(), timeout=10))
         preload_dispvm = self.disp_base.get_feat_preload()
-        self.assertEqual(len(old_preload), preload_max)
-        self.assertEqual(len(preload_dispvm), preload_max)
-        self.assertTrue(
-            set(old_preload).isdisjoint(preload_dispvm),
-            f"old_preload={old_preload} preload_dispvm={preload_dispvm}",
+        self.assertEqual(
+            old_preload,
+            preload_dispvm,
+            msg=f"old_preload={old_preload} preload_dispvm={preload_dispvm}",
         )
 
-        logger.info("global refresh to be made")
         preload_max += 1
+        logger.info("global refill must work")
         self.adminvm.features["preload-dispvm-max"] = str(preload_max)
         self.loop.run_until_complete(self.wait_preload(preload_max))
-        del self.disp_base.features["preload-dispvm-max"]
+        old_old_preload = self.disp_base.get_feat_preload()
+        self.loop.run_until_complete(
+            self.cleanup_preload_run(self.disp_base, down_to=preload_max - 1)
+        )
         old_preload = self.disp_base.get_feat_preload()
+        self.assertEqual(len(old_preload), preload_max - 1)
+        self.assertIn(old_preload[0], old_old_preload)
         proc = self.loop.run_until_complete(
             asyncio.create_subprocess_exec("/usr/lib/qubes/preload-dispvm")
         )
-        self.loop.run_until_complete(asyncio.wait_for(proc.wait(), timeout=40))
+        try:
+            self.loop.run_until_complete(
+                asyncio.wait_for(proc.wait(), timeout=40)
+            )
+        except asyncio.TimeoutError:
+            debug_preload = self.disp_base.get_feat_preload()
+            for qube in debug_preload:
+                qube = self.app.domains[qube]
+                if qube.is_paused():
+                    self.loop.run_until_complete(
+                        asyncio.wait_for(qube.unpause(), timeout=5)
+                    )
+                self._run_cmd_and_log_output(
+                    qube, "systemtl --user is-system-running", user="user"
+                )
+                self._run_cmd_and_log_output(
+                    qube, "systemtl is-system-running", user="root"
+                )
+                self._run_cmd_and_log_output(
+                    qube, "systemd-analyze --no-pager --user blame", user="user"
+                )
+                self._run_cmd_and_log_output(
+                    qube, "systemd-analyze --no-pager blame", user="root"
+                )
+                self._run_cmd_and_log_output(
+                    qube, "journalctl --no-pager --user", user="user"
+                )
+                self._run_cmd_and_log_output(
+                    qube, "journalctl --no-pager", user="root"
+                )
+            raise
         preload_dispvm = self.disp_base.get_feat_preload()
-        self.assertEqual(len(old_preload), preload_max)
+        self.assertIn(old_preload[0], preload_dispvm)
         self.assertEqual(len(preload_dispvm), preload_max)
-        self.assertTrue(
-            set(old_preload).isdisjoint(preload_dispvm),
-            f"old_preload={old_preload} preload_dispvm={preload_dispvm}",
-        )
 
         self.app.default_dispvm = None
         logger.info("end")

qubes/vm/mix/dvmtemplate.py

@@ -63,7 +63,7 @@ def on_domain_loaded(self, event) -> None:
         # pylint: disable=unused-argument
         assert isinstance(self, qubes.vm.BaseVM)
         changes = False
-        # Preloading began and host rebooted and autostart event didn't run yet.
+        # Began preloading, host rebooted, autostart script didn't run yet.
         old_preload = self.get_feat_preload()
         clean_preload = old_preload.copy()
         for unwanted_disp in old_preload:
@@ -411,7 +411,6 @@ def __on_property_set_template(
 
     @qubes.events.handler(
         "domain-preload-dispvm-used",
-        "domain-preload-dispvm-autostart",
         "domain-preload-dispvm-start",
     )
     async def on_domain_preload_dispvm_used(
@@ -423,14 +422,11 @@ async def on_domain_preload_dispvm_used(
         **kwargs,  # pylint: disable=unused-argument
     ) -> None:
         """
-        Offloads on excess and preload on vacancy. On ``autostart``, the
-        preloaded list is emptied before preloading.
+        Offloads on excess and preload on vacancy.
 
         :param str event: Event which was fired. Events have the prefix \
-            ``domain-preload-dispvm-``. If the suffix is ``autostart``, the \
-            preload list is emptied before attempting to preload. If the \
-            suffix is ``used`` or ``start``, tries to preload until it fills \
-            gaps.
+            ``domain-preload-dispvm-``. It always tries to preload until it \
+            fills the gaps if there is enough memory.
         :param qubes.vm.dispvm.DispVM dispvm: Disposable that was used
         :param str reason: Why the event was fired
         :param float delay: Proceed only after sleeping that many seconds
@@ -454,9 +450,7 @@ async def on_domain_preload_dispvm_used(
         if delay:
             await asyncio.sleep(delay)
 
-        if event == "autostart":
-            self.remove_preload_excess(0, reason="event autostart was called")
-        elif not self.can_preload():
+        if not self.can_preload():
             self.remove_preload_excess(reason="there may be absent qubes")
             # Absent qubes might be removed above.
             if not self.can_preload():