Improve tests traceability, add test for Systemd dependency cycles (#3917)

* Add test checking journal logs for dependency cycles
* Run some test cases to get their output also when full init fails
* Remove high timeouts from the times when GHA couldn't use KVM
* Enable logging durations for future optimizations

.github/workflows/test.yaml

@@ -74,7 +74,7 @@ jobs:
 
       - name: Run tests
         run: |
-          ./tests/run_tests.sh
+          ./tests/run_tests.sh --durations=0 --durations-min=5.0
 
       - name: Archive logs
         uses: actions/upload-artifact@v4

tests/smoke_test/test_basic.py

@@ -8,7 +8,7 @@ _LOGGER = logging.getLogger(__name__)
 
 
 @pytest.mark.dependency()
-@pytest.mark.timeout(600)
+@pytest.mark.timeout(120)
 def test_init(shell):
     def check_container_running(container_name):
         out = shell.run_check(
@@ -35,7 +35,6 @@ def test_init(shell):
     _LOGGER.info("%s", "\n".join(output))
 
 
-@pytest.mark.dependency(depends=["test_init"])
 def test_rauc_status(shell, shell_json):
     rauc_status = shell.run_check("rauc status --output-format=shell --detailed")
     # RAUC_BOOT_PRIMARY won't be set if correct grub env is missing
@@ -55,7 +54,6 @@ def test_rauc_status(shell, shell_json):
     assert f"RAUC_SLOT_STATUS_BUNDLE_VERSION_{booted_idx + 1}='{expected_version}'" in rauc_status
 
 
-@pytest.mark.dependency(depends=["test_init"])
 def test_dmesg(shell):
     output = shell.run_check("dmesg")
     _LOGGER.info("%s", "\n".join(output))
@@ -67,17 +65,22 @@ def test_supervisor_logs(shell):
     _LOGGER.info("%s", "\n".join(output))
 
 
-@pytest.mark.dependency(depends=["test_init"])
 def test_systemctl_status(shell):
     output = shell.run_check("systemctl --no-pager -l status -a || true")
     _LOGGER.info("%s", "\n".join(output))
 
-@pytest.mark.dependency(depends=["test_init"])
+
 def test_systemctl_check_no_failed(shell):
     output = shell.run_check("systemctl --no-pager -l list-units --state=failed")
     assert "0 loaded units listed." in output, f"Some units failed:\n{"\n".join(output)}"
 
 
+def test_systemctl_no_cycles(shell):
+    # we don't have systemd-analyze available, so check it naively using grep
+    output = shell.run_check("journalctl -b0 | grep 'ordering cycle' || true")
+    assert not output, f"Found Systemd dependency cycles:\n{"\n".join(output)}"
+
+
 @pytest.mark.dependency(depends=["test_init"])
 def test_custom_swap_size(shell, target):
     output = shell.run_check("stat -c '%s' /mnt/data/swapfile")
@@ -103,7 +106,6 @@ def test_no_swap(shell, target):
     assert swapon == [], f"Swapfile still exists: {swapon}"
 
 
-@pytest.mark.dependency(depends=["test_init"])
 def test_kernel_not_tainted(shell):
     """Check if the kernel is not tainted - do it at the end of the
     test suite to increase the chance of catching issues."""

tests/smoke_test/test_offline.py

@@ -27,7 +27,7 @@ def _check_connectivity(shell, *, connected):
         raise AssertionError(f"expecting connected but all targets are down")
 
 
-@pytest.mark.timeout(300)  # takes quite a while also because of 90s NTP sync timeout
+@pytest.mark.timeout(120)
 @pytest.mark.usefixtures("without_internet")
 def test_ha_runs_offline(shell):
     def check_container_running(container_name):

tests/supervisor_test/test_supervisor.py

@@ -16,7 +16,7 @@ def stash() -> dict:
 
 
 @pytest.mark.dependency()
-@pytest.mark.timeout(600)
+@pytest.mark.timeout(120)
 def test_start_supervisor(shell, shell_json):
     def check_container_running(container_name):
         out = shell.run_check(f"docker container inspect -f '{{{{.State.Status}}}}' {container_name} || true")
@@ -55,7 +55,7 @@ def test_check_supervisor(shell_json):
 
 
 @pytest.mark.dependency(depends=["test_check_supervisor"])
-@pytest.mark.timeout(300)
+@pytest.mark.timeout(120)
 def test_update_supervisor(shell_json):
     supervisor_info = shell_json("ha supervisor info --no-progress --raw-json")
     supervisor_version = supervisor_info.get("data").get("version")
@@ -153,7 +153,7 @@ def test_addon_uninstall(shell_json):
 
 
 @pytest.mark.dependency(depends=["test_supervisor_is_updated"])
-@pytest.mark.timeout(450)
+@pytest.mark.timeout(120)
 def test_restart_supervisor(shell, shell_json):
     result = shell_json("ha supervisor restart --no-progress --raw-json")
     assert result.get("result") == "ok", f"Supervisor restart failed: {result}"