fixes for nixos 24.11

setup.py

@@ -28,7 +28,7 @@
     namespace_packages=["fc"],
     install_requires=[
         "colorama",  # ==0.3.3',
-        "abaez.consulate==1.1.0",
+        "consulate >= 1.1.0",
         "psutil",  # ==5.4.2',
         "PyYaml>=5.3.1",
         "requests",  # ==2.11.1',

src/fc/qemu/agent.py

@@ -3,11 +3,10 @@
 import datetime
 import distutils.spawn
 import fcntl
-import glob
+import importlib.resources
 import json
 import math
 import os
-import os.path as p
 import shutil
 import socket
 import subprocess
@@ -21,7 +20,6 @@
 import colorama
 import consulate
 import consulate.models.agent
-import pkg_resources
 import requests
 import yaml
 
@@ -272,9 +270,9 @@ class Agent(object):
     timeout_graceful = 10
 
     system_config_template = Path("etc/qemu/qemu.vm.cfg.in")
-    builtin_config_template = Path(
-        pkg_resources.resource_filename(__name__, "qemu.vm.cfg.in")
-    )
+    # XXX the importlib schema requiring a context manager
+    # is not helpful here.
+    builtin_config_template = Path(__file__).parent / "qemu.vm.cfg.in"
     consul_token = None
     consul_generation = -1
 

tests/conftest.py

@@ -5,8 +5,8 @@
 import time
 import traceback
 from pathlib import Path
+from subprocess import getoutput
 
-import pkg_resources
 import pytest
 import structlog
 
@@ -66,7 +66,8 @@ def test_logger(logger, method_name, event):
                 result += fc.qemu.logging.prefix(event_prefix, output)
 
         # Ensure we get something to read on stdout in case we have errors.
-        print(result)
+        reltime = time.time() - util.test_log_start
+        print(f"{reltime:08.4f} {result}")
         if stack:
             print(stack)
         if exc:
@@ -95,6 +96,18 @@ def test_logger(logger, method_name, event):
                 util.log_data.extend(exc.splitlines())
         raise structlog.DropEvent
 
+    def test_log_print(*args):
+        """A helper for tests to insert output into the stdout log.
+
+        This adds the same timestamps as the default output for the
+        log and avoids this to become part of the output content that
+        we run assertions on.
+        """
+        reltime = time.time() - util.test_log_start
+        print(f"{reltime:08.4f}", *args)
+
+    util.test_log_print = test_log_print
+
     structlog.configure(
         processors=(
             ([structlog.processors.format_exc_info] if log_exceptions else [])
@@ -108,6 +121,7 @@ def reset_structlog(setup_structlog):
     from fc.qemu import util
 
     util.log_data = []
+    util.test_log_start = time.time()
     util.test_log_options = {"show_methods": [], "show_events": []}
 
 
@@ -173,37 +187,15 @@ def clean():
 
     yield
     clean()
-
-    print(
-        subprocess.check_output(
-            "free && sync && echo 3 > /proc/sys/vm/drop_caches && free",
-            shell=True,
-        ).decode("ascii")
-    )
-    print(
-        subprocess.check_output(
-            "ceph df",
-            shell=True,
-        ).decode("ascii")
-    )
     print(
-        subprocess.check_output(
-            "ps auxf",
-            shell=True,
-        ).decode("ascii")
-    )
-    print(
-        subprocess.check_output(
-            "df -h",
-            shell=True,
-        ).decode("ascii")
-    )
-    print(
-        subprocess.check_output(
-            "rbd showmapped",
-            shell=True,
-        ).decode("ascii")
+        getoutput("free && sync && echo 3 > /proc/sys/vm/drop_caches && free")
     )
+    print(getoutput("ceph df"))
+    print(getoutput("ps auxf"))
+    print(getoutput("df -h"))
+    print(getoutput("rbd showmapped"))
+    print(getoutput("journalctl --since -30s"))
+    print(getoutput("tail -n 50 /var/log/vm/*"))
 
 
 @pytest.fixture(autouse=True)
@@ -224,8 +216,8 @@ def vm(clean_environment, monkeypatch, tmpdir):
     import fc.qemu.hazmat.qemu
 
     monkeypatch.setattr(fc.qemu.hazmat.qemu.Qemu, "guestagent_timeout", 0.1)
-    fixtures = pkg_resources.resource_filename(__name__, "fixtures")
-    shutil.copy(fixtures + "/simplevm.yaml", "/etc/qemu/vm/simplevm.cfg")
+    simplevm_cfg = Path(__file__).parent / "fixtures" / "simplevm.yaml"
+    shutil.copy(simplevm_cfg, "/etc/qemu/vm/simplevm.cfg")
     Path("/etc/qemu/vm/.simplevm.cfg.staging").unlink(missing_ok=True)
 
     vm = Agent("simplevm")

tests/hazmat/test_ceph.py

@@ -54,7 +54,7 @@ def test_multiple_images_raises_error(ceph_inst):
 @pytest.mark.timeout(60)
 @pytest.mark.live()
 def test_rbd_pool_migration(ceph_inst, patterns) -> None:
-    ceph_inst.cfg["tmp_size"] = 50 * 1024 * 1024
+    ceph_inst.cfg["tmp_size"] = 500 * 1024 * 1024
     ceph_inst.cfg["swap_size"] = 50 * 1024 * 1024
     ceph_inst.cfg["root_size"] = 50 * 1024 * 1024
     rbd.RBD().create(
@@ -83,6 +83,9 @@ def test_rbd_pool_migration(ceph_inst, patterns) -> None:
     first_start.optional(
         """
 waiting interval=0 machine=simplevm remaining=4 subsystem=ceph volume=rbd.hdd/simplevm.tmp
+sgdisk> Setting name!
+sgdisk> partNum is 0
+mkfs.xfs>       mkfs.xfs: small data volume, ignoring data volume stripe unit 128 and stripe width 128
 """
     )
     first_start.in_order(
@@ -138,8 +141,6 @@ def test_rbd_pool_migration(ceph_inst, patterns) -> None:
 sgdisk> The operation has completed successfully.
 sgdisk machine=simplevm returncode=0 subsystem=ceph volume=rbd.hdd/simplevm.tmp
 sgdisk args=-a 8192 -n 1:8192:0 -c "1:tmp" -t 1:8300 "/dev/rbd/rbd.hdd/simplevm.tmp" machine=simplevm subsystem=ceph volume=rbd.hdd/simplevm.tmp
-sgdisk> Setting name!
-sgdisk> partNum is 0
 sgdisk> The operation has completed successfully.
 sgdisk machine=simplevm returncode=0 subsystem=ceph volume=rbd.hdd/simplevm.tmp
 partprobe args=/dev/rbd/rbd.hdd/simplevm.tmp machine=simplevm subsystem=ceph volume=rbd.hdd/simplevm.tmp

tests/hazmat/test_volume.py

@@ -159,7 +159,7 @@ def test_volume_mkswap(ceph_inst):
 
 @pytest.mark.timeout(60)
 def test_volume_tmp_mkfs(tmp_spec):
-    tmp_spec.desired_size = 100 * 1024 * 1024
+    tmp_spec.desired_size = 400 * 1024 * 1024
     tmp_spec.ensure_presence()
     with tmp_spec.volume.mapped():
         tmp_spec.mkfs()
@@ -205,7 +205,7 @@ def test_mount_should_fail_if_not_mapped(tmp_spec):
 @pytest.mark.timeout(60)
 @pytest.mark.live()
 def test_mount_snapshot(tmp_spec):
-    tmp_spec.desired_size = 100 * 1024 * 1024
+    tmp_spec.desired_size = 500 * 1024 * 1024
     tmp_spec.ensure_presence()
     volume = tmp_spec.volume
     with volume.mapped():

tests/test_agent.py

@@ -1,9 +1,7 @@
-import os
 import shutil
 from pathlib import Path
 
 import mock
-import pkg_resources
 import psutil
 import pytest
 
@@ -14,7 +12,7 @@
 
 @pytest.fixture
 def simplevm_cfg(monkeypatch):
-    fixtures = Path(pkg_resources.resource_filename(__name__, "fixtures"))
+    fixtures = Path(__file__).parent / "fixtures"
     source = fixtures / "simplevm.yaml"
     # The Qemu prefix gets adjusted automatically in the synhetic_root
     # auto-use fixture that checks whether this is a live test or not.

tests/test_binenv.py

@@ -38,3 +38,4 @@ def test_no_unexpected_binaries():
 @pytest.mark.unit
 def test_ensure_critical_module_imports():
     import rados  # noqa
+    import structlog  # noqa

tests/test_vm.py

@@ -96,8 +96,6 @@ def test_simple_vm_lifecycle_start_stop(vm, patterns):
 sgdisk> The operation has completed successfully.
 sgdisk machine=simplevm returncode=0 subsystem=ceph volume=rbd.ssd/simplevm.tmp
 sgdisk args=-a 8192 -n 1:8192:0 -c "1:tmp" -t 1:8300 "/dev/rbd/rbd.ssd/simplevm.tmp" machine=simplevm subsystem=ceph volume=rbd.ssd/simplevm.tmp
-sgdisk> Setting name!
-sgdisk> partNum is 0
 sgdisk> The operation has completed successfully.
 sgdisk machine=simplevm returncode=0 subsystem=ceph volume=rbd.ssd/simplevm.tmp
 partprobe args=/dev/rbd/rbd.ssd/simplevm.tmp machine=simplevm subsystem=ceph volume=rbd.ssd/simplevm.tmp
@@ -151,6 +149,8 @@ def test_simple_vm_lifecycle_start_stop(vm, patterns):
 sgdisk> Creating new GPT entries in memory.
 rbd> /dev/rbd0
 waiting interval=0 machine=simplevm remaining=... subsystem=ceph volume=rbd.ssd/simplevm.tmp
+sgdisk> Setting name!
+sgdisk> partNum is 0
 """
     )
 
@@ -163,7 +163,7 @@ def test_simple_vm_lifecycle_start_stop(vm, patterns):
 fc-create-vm> $ rbd --format json --id host1 snap ls rbd.hdd/fc-21.05-dev
 fc-create-vm> Snapshots:
 fc-create-vm> snapid name size
-fc-create-vm> 4 v1 104857600
+fc-create-vm> 4 v1 524288000
 fc-create-vm> $ rbd --id host1 clone rbd.hdd/fc-21.05-dev@v1 rbd.ssd/simplevm.root
 fc-create-vm>
 fc-create-vm> Finished
@@ -375,7 +375,10 @@ def test_vm_not_running_here(vm, capsys):
     )
 
 
-@pytest.mark.timeout(60)
+# This test is really slow and it appears that a lot of time is due to
+# locking/unlocking (or rather: breaking locks) in Ceph taking around 5
+# seconds each time ...
+@pytest.mark.timeout(90)
 @pytest.mark.live
 def test_crashed_vm_clean_restart(vm):
     util.test_log_options["show_events"] = [
@@ -386,6 +389,7 @@ def test_crashed_vm_clean_restart(vm):
         "shutdown",
     ]
 
+    util.test_log_print("=== Running status() ===")
     vm.status()
 
     assert get_log() == Ellipsis(
@@ -396,7 +400,9 @@ def test_crashed_vm_clean_restart(vm):
 rbd-status machine=simplevm presence=missing subsystem=ceph volume=rbd.ssd/simplevm.tmp"""
     )
 
+    util.test_log_print("=== Running ensure() ... ===")
     vm.ensure()
+    util.test_log_print("=== Running status() ===")
     vm.status()
     assert get_log() == Ellipsis(
         """\
@@ -412,11 +418,13 @@ def test_crashed_vm_clean_restart(vm):
 rbd-status locker=('client...', 'host1') machine=simplevm subsystem=ceph volume=rbd.ssd/simplevm.tmp"""
     )
 
+    util.test_log_print("=== Killing the qemu process ===")
     p = vm.qemu.proc()
     p.kill()
     p.wait(2)
     get_log()
 
+    util.test_log_print("=== Running status() ===")
     vm.status()
     assert get_log() == Ellipsis(
         """\
@@ -426,8 +434,10 @@ def test_crashed_vm_clean_restart(vm):
 rbd-status locker=('client...', 'host1') machine=simplevm subsystem=ceph volume=rbd.ssd/simplevm.tmp"""
     )
 
+    util.test_log_print("=== Running ensure() ===")
     vm.ensure()
 
+    util.test_log_print("=== Running status() ===")
     vm.status()
     assert get_log() == Ellipsis(
         """\
@@ -452,7 +462,9 @@ def test_crashed_vm_clean_restart(vm):
         "clean",
         "rbd-status",
     ]
+    util.test_log_print("=== Running stop() ===")
     vm.stop()
+    util.test_log_print("=== Running status() ===")
     vm.status()
     assert get_log() == Ellipsis(
         """\