Late GUID for preloaded disposables

- 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
Requires: QubesOS/qubes-core-admin-client#359

Author: ben-grande

Makefile

@@ -179,7 +179,6 @@ all:
 
 install:
 ifeq ($(OS),Linux)
-	$(MAKE) install -C linux/autostart
 	$(MAKE) install -C linux/systemd
 	$(MAKE) install -C linux/aux-tools
 	$(MAKE) install -C linux/system-config

linux/autostart/Makefile

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

linux/autostart/qubes-preload-dispvm.desktop

@@ -29,11 +29,22 @@
 from unittest.mock import patch, mock_open
 import asyncio
 import sys
+import logging
 
 import qubes.config
 import qubes.tests
 import qubesadmin.exc
 
+# nose will duplicate this logger.
+logger = logging.getLogger(__name__)
+logger.setLevel(logging.DEBUG)
+handler = logging.StreamHandler()
+formatter = logging.Formatter(
+    "%(asctime)s: %(funcName)s: %(levelname)s: %(message)s"
+)
+handler.setFormatter(formatter)
+logger.addHandler(handler)
+
 
 class TC_04_DispVM(qubes.tests.SystemTestCase):
     def setUp(self):
@@ -183,6 +194,7 @@ def test_011_failed_start_timeout(self):
 
 class TC_20_DispVMMixin(object):
     def setUp(self):  # pylint: disable=invalid-name
+        logger.info("start")
         super(TC_20_DispVMMixin, self).setUp()
         if "whonix-g" in self.template:
             self.skipTest(
@@ -205,8 +217,10 @@ def setUp(self):  # pylint: disable=invalid-name
             "--",
             "qubesdb-read /name | tr -d '\n'",
         ]
+        logger.info("end")
 
     def tearDown(self):  # pylint: disable=invalid-name
+        logger.info("start")
         if "gui" in self.disp_base.features:
             del self.disp_base.features["gui"]
         old_preload = self.disp_base.get_feat_preload()
@@ -215,6 +229,7 @@ def tearDown(self):  # pylint: disable=invalid-name
         self.loop.run_until_complete(asyncio.gather(*tasks))
         self.disp_base.features["preload-dispvm-max"] = False
         super(TC_20_DispVMMixin, self).tearDown()
+        logger.info("end")
 
     def _test_event_handler(
         self, vm, event, *args, **kwargs
@@ -233,7 +248,38 @@ async def no_preload(self):
         await asyncio.sleep(0)
         self.disp_base.features["preload-dispvm-max"] = False
 
+    async def wait_preload(
+        self, preload_max, wait_pause=True, fail_on_timeout=True
+    ):
+        """Waiting for pause avoids objects leaking."""
+        logger.info("start")
+        for _ in range(60):
+            if len(self.disp_base.get_feat_preload()) == preload_max:
+                break
+            await asyncio.sleep(1)
+        else:
+            if fail_on_timeout:
+                self.fail("didn't preload in time")
+        if not wait_pause:
+            logger.info("end")
+            return
+        preload_dispvm = self.disp_base.get_feat_preload()
+        preload_unfinished = preload_dispvm
+        for _ in range(60):
+            for qube in preload_unfinished.copy():
+                if self.app.domains[qube].is_paused():
+                    preload_unfinished.remove(qube)
+                    continue
+            if not preload_unfinished:
+                break
+            await asyncio.sleep(1)
+        else:
+            if fail_on_timeout:
+                self.fail("last preloaded didn't pause in time")
+        logger.info("end")
+
     async def run_preload_proc(self):
+        logger.info("start")
         proc = await asyncio.create_subprocess_exec(
             *self.preload_cmd,
             stdout=asyncio.subprocess.PIPE,
@@ -245,8 +291,11 @@ async def run_preload_proc(self):
             proc.terminate()
             await proc.wait()
             raise
+        finally:
+            logger.info("end")
 
     async def run_preload(self):
+        logger.info("start")
         appvm = self.disp_base
         dispvm = appvm.get_feat_preload()[0]
         dispvm = self.app.domains[dispvm]
@@ -324,6 +373,7 @@ async def run_preload(self):
         next_preload_list = appvm.get_feat_preload()
         self.assertTrue(next_preload_list)
         self.assertNotIn(dispvm_name, next_preload_list)
+        logger.info("end")
 
     def test_010_dvm_run_simple(self):
         dispvm = self.loop.run_until_complete(
@@ -353,6 +403,7 @@ def test_012_dvm_run_preload_low_mem(self):
 
     async def _test_012_dvm_run_preload_low_mem(self):
         # pylint: disable=unspecified-encoding
+        logger.info("start")
         unpatched_open = open
 
         def mock_open_mem(file, *args, **kwargs):
@@ -362,135 +413,107 @@ def mock_open_mem(file, *args, **kwargs):
             return unpatched_open(file, *args, **kwargs)
 
         with patch("builtins.open", side_effect=mock_open_mem):
-            self.disp_base.features["preload-dispvm-max"] = "2"
-            for _ in range(15):
-                if len(self.disp_base.get_feat_preload()) == 2:
-                    break
-                await asyncio.sleep(1)
+            preload_max = 2
+            self.disp_base.features["preload-dispvm-max"] = str(preload_max)
+            await self.wait_preload(preload_max, fail_on_timeout=False)
             self.assertEqual(1, len(self.disp_base.get_feat_preload()))
+        logger.info("end")
 
     def test_013_dvm_run_preload_gui(self):
-        """Test preloading with GUI feature enabled"""
+        """Test preloading with GUI feature enabled and use after pause."""
         self.loop.run_until_complete(self._test_013_dvm_run_preload_gui())
 
     async def _test_013_dvm_run_preload_gui(self):
+        logger.info("start")
+        preload_max = 1
         self.disp_base.features["gui"] = True
-        self.disp_base.features["preload-dispvm-max"] = "1"
-        for _ in range(10):
-            if len(self.disp_base.get_feat_preload()) == 1:
-                break
-            await asyncio.sleep(1)
-        else:
-            self.fail("didn't preload in time")
+        self.disp_base.features["preload-dispvm-max"] = str(preload_max)
+        await self.wait_preload(preload_max)
         await self.run_preload()
+        logger.info("end")
 
     def test_014_dvm_run_preload_nogui(self):
-        """Test preloading with GUI feature disabled"""
+        """Test preloading with GUI feature disabled and use before pause."""
         self.loop.run_until_complete(self._test_014_dvm_run_preload_nogui())
 
     async def _test_014_dvm_run_preload_nogui(self):
+        logger.info("start")
+        preload_max = 1
         self.disp_base.features["gui"] = False
-        self.disp_base.features["preload-dispvm-max"] = "1"
-        for _ in range(10):
-            if len(self.disp_base.get_feat_preload()) == 1:
-                break
-            await asyncio.sleep(1)
-        else:
-            self.fail("didn't preload in time")
+        self.disp_base.features["preload-dispvm-max"] = str(preload_max)
+        await self.wait_preload(preload_max, wait_pause=False)
         self.preload_cmd.insert(1, "--no-gui")
         await self.run_preload()
+        logger.info("end")
 
     def test_015_dvm_run_preload_race_more(self):
         """Test race requesting multiple preloaded qubes"""
         self.loop.run_until_complete(self._test_015_dvm_run_preload_race_more())
 
-    async def _test_preload_wait_pause(self, preload_max):
-        """Waiting for pause avoids objects leaking."""
-        for _ in range(60):
-            if len(self.disp_base.get_feat_preload()) == preload_max:
-                break
-            await asyncio.sleep(1)
-        else:
-            self.fail("didn't preload in time")
-        preload_dispvm = self.disp_base.get_feat_preload()
-        preload_unfinished = preload_dispvm
-        for _ in range(60):
-            for qube in preload_unfinished.copy():
-                if self.app.domains[qube].is_paused():
-                    preload_unfinished.remove(qube)
-                    continue
-            if not preload_unfinished:
-                break
-            await asyncio.sleep(1)
-        else:
-            self.fail("last preloaded didn't pause in time")
-
     async def _test_015_dvm_run_preload_race_more(self):
         # The limiting factor is how much memory is available on OpenQA and the
         # unreasonable memory allocated before the qube is paused due to:
         #   https://github.com/QubesOS/qubes-issues/issues/9917
         # Whonix (Kicksecure) 17 fail more due to memory consumption. From the
         # templates deployed by default, only Debian and Fedora survives due to
         # using less memory than the other OSes.
+        logger.info("start")
         preload_max = 4
         os_dist = self.disp_base.features.check_with_template("os-distribution")
         if os_dist in ["whonix", "kicksecure"]:
             preload_max -= 1
         self.disp_base.features["preload-dispvm-max"] = str(preload_max)
-        await self._test_preload_wait_pause(preload_max)
+        await self.wait_preload(preload_max)
         old_preload = self.disp_base.get_feat_preload()
         tasks = [self.run_preload_proc() for _ in range(preload_max)]
         targets = await asyncio.gather(*tasks)
-        await self._test_preload_wait_pause(preload_max)
+        await self.wait_preload(preload_max)
         preload_dispvm = self.disp_base.get_feat_preload()
         self.assertTrue(set(old_preload).isdisjoint(preload_dispvm))
         self.assertEqual(len(targets), preload_max)
         self.assertEqual(len(targets), len(set(targets)))
+        logger.info("end")
 
     def test_016_dvm_run_preload_race_less(self):
         """Test race requesting preloaded qube while the maximum is zeroed."""
         self.loop.run_until_complete(self._test_016_dvm_run_preload_race_less())
 
     async def _test_016_dvm_run_preload_race_less(self):
-        self.disp_base.features["preload-dispvm-max"] = "1"
-        for _ in range(60):
-            if len(self.disp_base.get_feat_preload()) == 1:
-                break
-            await asyncio.sleep(1)
-        else:
-            self.fail("didn't preload in time")
+        logger.info("start")
+        preload_max = 1
+        self.disp_base.features["preload-dispvm-max"] = str(preload_max)
+        await self.wait_preload(preload_max, wait_pause=False)
         tasks = [self.run_preload_proc(), self.no_preload()]
         target = await asyncio.gather(*tasks)
         target_dispvm = target[0]
         self.assertTrue(target_dispvm.startswith("disp"))
+        logger.info("end")
 
     def test_017_dvm_run_preload_autostart(self):
+        logger.info("start")
+        preload_max = 1
         proc = self.loop.run_until_complete(
             asyncio.create_subprocess_exec("/usr/lib/qubes/preload-dispvm")
         )
         self.loop.run_until_complete(
             asyncio.wait_for(proc.communicate(), timeout=10)
         )
         self.assertEqual(self.disp_base.get_feat_preload(), [])
-        self.disp_base.features["preload-dispvm-max"] = "1"
-        for _ in range(10):
-            if len(self.disp_base.get_feat_preload()) == 1:
-                break
-            self.loop.run_until_complete(asyncio.sleep(1))
-        else:
-            self.fail("didn't preload in time")
+        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=30))
         preload_dispvm = self.disp_base.get_feat_preload()
-        self.assertEqual(len(old_preload), 1)
-        self.assertEqual(len(preload_dispvm), 1)
+        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}",
         )
+        logger.info("end")
 
     @unittest.skipUnless(
         spawn.find_executable("xdotool"), "xdotool not installed"