drakrun: VM unit test and refactor (#496)

* add VM unit tests
* add try_run wrapper
* implement new functions in VirtualMachine class
* remove raw xl commands from xtf tests
* configure live logging in pytest

Co-authored-by: Hubert Jasudowicz <hubert.jasudowicz@gmail.com>

drakrun/drakrun/draksetup.py

@@ -201,11 +201,12 @@ def perform_xtf():
         tmpf.write(test_cfg)
         tmpf.flush()
 
+        test_hvm64 = VirtualMachine(None, None, "test-hvm64-example", tmpf.name)
         logging.info('Checking if the test domain already exists...')
-        subprocess.run('xl destroy test-hvm64-example', shell=True)
+        test_hvm64.destroy()
 
         logging.info('Creating new test domain...')
-        subprocess.run(f'xl create -p {tmpf.name}', shell=True, stderr=subprocess.STDOUT, timeout=30, check=True)
+        test_hvm64.create(pause=True, timeout=30)
 
         module_dir = os.path.dirname(os.path.realpath(__file__))
         test_altp2m_tool = os.path.join(module_dir, "tools", "test-altp2m")
@@ -216,12 +217,12 @@ def perform_xtf():
         except subprocess.CalledProcessError as e:
             output = e.output.decode('utf-8', 'replace')
             logging.error(f'Failed to enable altp2m on domain. Your hardware might not support Extended Page Tables. Logs:\n{output}')
-            subprocess.run('xl destroy test-hvm64-example', shell=True)
+            test_hvm64.destroy()
             return False
 
         logging.info('Performing simple XTF test...')
         p = subprocess.Popen(['xl', 'console', 'test-hvm64-example'], stdout=subprocess.PIPE, stderr=subprocess.PIPE)
-        subprocess.run('xl unpause test-hvm64-example', shell=True, stderr=subprocess.STDOUT, timeout=30, check=True)
+        test_hvm64.unpause(timeout=30)
         stdout_b, _ = p.communicate(timeout=10)
 
         stdout_text = stdout_b.decode('utf-8')
@@ -342,17 +343,13 @@ def install(vcpus, memory, storage_backend, disk_size, iso_path, zfs_tank_name,
     )
     install_info.save()
 
-    try:
-        subprocess.check_output('xl uptime vm-0', shell=True, stderr=subprocess.STDOUT)
-    except subprocess.CalledProcessError:
-        pass
-    else:
-        logging.info('Detected that vm-0 is already running, stopping it.')
-        subprocess.run('xl destroy vm-0', shell=True, check=True)
+    backend = get_storage_backend(install_info)
+
+    vm0 = VirtualMachine(backend, 0)
+    vm0.destroy()
 
     generate_vm_conf(install_info, 0)
 
-    backend = get_storage_backend(install_info)
     backend.initialize_vm0_volume(disk_size)
 
     try:
@@ -372,11 +369,7 @@ def install(vcpus, memory, storage_backend, disk_size, iso_path, zfs_tank_name,
 
     cfg_path = os.path.join(VM_CONFIG_DIR, "vm-0.cfg")
 
-    try:
-        subprocess.run('xl create {}'.format(shlex.quote(cfg_path)), shell=True, check=True)
-    except subprocess.CalledProcessError:
-        logging.exception("Failed to launch VM vm-0")
-        return
+    vm0.create()
 
     logging.info("-" * 80)
     logging.info("Initial VM setup is complete and the vm-0 was launched.")
@@ -543,9 +536,9 @@ def postinstall(report, generate_usermode):
     install_info = InstallInfo.load()
     storage_backend = get_storage_backend(install_info)
 
-    vm = VirtualMachine(storage_backend, 0)
+    vm0 = VirtualMachine(storage_backend, 0)
 
-    if vm.is_running is False:
+    if vm0.is_running is False:
         logging.exception("vm-0 is not running")
         return
 
@@ -597,7 +590,7 @@ def postinstall(report, generate_usermode):
     # Create vm-0 snapshot, and destroy it
     # WARNING: qcow2 snapshot method is a noop. fresh images are created on the fly
     # so we can't keep the vm-0 running
-    subprocess.check_output('xl save vm-0 ' + os.path.join(VOLUME_DIR, "snapshot.sav"), shell=True)
+    vm0.save(os.path.join(VOLUME_DIR, "snapshot.sav"))
     logging.info("Snapshot was saved succesfully.")
 
     # Memory state is frozen, we can't do any writes to persistent storage

drakrun/drakrun/test/pytest.ini

@@ -1,3 +1,7 @@
 [pytest]
 markers =
     incremental: incremental tests
+log_cli = 1
+log_cli_level = DEBUG
+log_cli_format = %(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)
+log_cli_date_format=%Y-%m-%d %H:%M:%S

drakrun/drakrun/test/test_vm.py

@@ -0,0 +1,265 @@
+import pytest
+
+from drakrun.config import InstallInfo
+from drakrun.vm import VirtualMachine
+from drakrun.util import safe_delete
+from _pytest.monkeypatch import MonkeyPatch
+from common_utils import remove_files, tool_exists
+import tempfile
+import subprocess
+import os
+import re
+import logging
+
+
+@pytest.fixture(scope="session")
+def monkeysession(request):
+    mp = MonkeyPatch()
+    yield mp
+    mp.undo()
+
+
+@pytest.fixture(scope="module")
+def patch(monkeysession):
+    if not tool_exists('xl'):
+        pytest.skip("xen is not found")
+
+    def install_patch():
+        return InstallInfo(
+            vcpus=1,
+            memory=512,
+            storage_backend='qcow2',
+            disk_size='200M',
+            iso_path=None,  # not being required
+            zfs_tank_name=None,
+            lvm_volume_group=None,
+            enable_unattended=None,
+            iso_sha256=None
+        )
+    monkeysession.setattr(InstallInfo, "load", install_patch)
+    monkeysession.setattr(InstallInfo, "try_load", install_patch)
+
+    # being yielded so the the monkeypatch doesn't start cleanup if returned
+    yield monkeysession
+
+
+@pytest.fixture(scope="module")
+def test_vm(patch, config):
+    test_vm = VirtualMachine(None, 0, "test-hvm64-example", config)
+
+    yield test_vm
+
+
+@pytest.fixture(scope="module")
+def config():
+    tmpf = tempfile.NamedTemporaryFile(delete=False).name
+    module_dir = os.path.join(os.path.dirname(os.path.realpath(__file__)), '..')
+    cfg_path = os.path.join(module_dir, "tools", "test-hvm64-example.cfg")
+    firmware_path = os.path.join(module_dir, "tools", "test-hvm64-example")
+
+    with open(cfg_path, 'r') as f:
+        test_cfg = f.read().replace('{{ FIRMWARE_PATH }}', firmware_path).encode('utf-8')
+
+    with open(tmpf, 'wb') as f:
+        f.write(test_cfg)
+
+    yield tmpf
+    safe_delete(tmpf)
+
+
+@pytest.fixture(scope="module")
+def snapshot_file():
+    tmpf = tempfile.NamedTemporaryFile(delete=False).name
+    yield tmpf
+    safe_delete(tmpf)
+
+
+def get_vm_state(vm_name: str) -> str:
+    out_lines = subprocess.check_output("xl list", shell=True).decode().split('\n')
+    # get the line with vm_name
+    out = next((line for line in out_lines if vm_name in line), None)
+    if out is None:
+        raise Exception(f"{vm_name} not found in xl list")
+    else:
+        state = re.sub(r' +', ' ', out).split(' ')[4].strip().strip('-')
+        return state
+
+
+def destroy_vm(vm_name: str) -> str:
+    if subprocess.run(f"xl list {vm_name}", shell=True, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL).returncode == 0:
+        subprocess.run(f"xl destroy {vm_name}", shell=True, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
+        logging.info(f"Destroying {vm_name}")
+
+
+@pytest.mark.incremental
+class TestVM:
+    def test_vm_name(self, patch):
+        logging.info("testing VM names")
+        vm = VirtualMachine(None, 0)
+        assert vm.vm_name == 'vm-0'
+        logging.info("testing VM names with new fmt")
+        vm = VirtualMachine(None, 0, "test-vm-{}")
+        assert vm.vm_name == 'test-vm-0'
+
+    def test_vm_create_and_is_running(self, config, test_vm):
+
+        # initial cleanup
+        destroy_vm(test_vm.vm_name)
+        assert test_vm.is_running is False
+
+        logging.info("testing vm create with pause=False")
+        test_vm.create(pause=False)
+        assert get_vm_state(test_vm.vm_name) != 'p'
+        assert test_vm.is_running is True
+
+        logging.info("testing vm create for a created VM")
+        with pytest.raises(Exception):
+            test_vm.create(pause=True)
+
+        # second run
+        destroy_vm(test_vm.vm_name)
+
+        logging.info("testing vm create with pause=True")
+        test_vm.create(pause=True)
+        assert get_vm_state(test_vm.vm_name) == 'p'
+
+        # destroy the vm
+        destroy_vm(test_vm.vm_name)
+
+        logging.info("testing vm create with non-existant file")
+        with pytest.raises(Exception):
+            new_vm = VirtualMachine(None, 0, "test-hvm64-example", '/tmp/unexitant-file')
+            new_vm.create()
+
+        logging.info("testing vm create with empty file")
+        with tempfile.NamedTemporaryFile() as tempf:
+            with pytest.raises(Exception):
+                new_vm = VirtualMachine(None, 0, "test-hvm64-example", tempf.name)
+                new_vm.create()
+
+        # check if vm is shutdown
+        with pytest.raises(Exception):
+            get_vm_state(test_vm.name)
+
+    def test_vm_unpause(self, test_vm):
+        test_vm.create(pause=True)
+        assert get_vm_state(test_vm.vm_name) == 'p'
+
+        logging.info("testing vm unpause")
+        test_vm.unpause()
+        assert get_vm_state(test_vm.vm_name) != 'p'
+
+        # it shows stderr but rc is 0
+
+        # logging.info("testing vm unpause on an unpaused VM")
+        # with pytest.raises(Exception):
+        #     test_vm.unpause()
+
+        # it is a short lived VM so we will create a new one whenever we unpause
+        destroy_vm(test_vm.vm_name)
+
+    def test_vm_save(self, test_vm, snapshot_file):
+        # test-hvm64-example VM can't be snapshotted in unpaused state
+        """
+        root@debian:/home/user/drakvuf-sandbox/drakrun/drakrun/test# xl create /tmp/tmpjyoganif && xl save -c test-hvm64-example /tmp/test.sav
+        Parsing config from /tmp/tmpjyoganif
+        libxl: error: libxl_qmp.c:1334:qmp_ev_lock_aquired: Domain 122:Failed to connect to QMP socket /var/run/xen/qmp-libxl-122: No such file or directory
+        unable to retrieve domain configuration
+        """
+
+        # test_vm.create(pause=True)
+        # test_vm.unpause()
+        # test_vm.save(snapshot_file, cont=True)
+        # assert get_vm_state(test_vm.vm_name) != 'p'
+
+        # reset
+
+        # destroy_vm(test_vm.vm_name)
+        test_vm.create(pause=True)
+        assert get_vm_state(test_vm.vm_name) == 'p'
+
+        logging.info("test vm save with pause=True")
+        test_vm.save(snapshot_file, pause=True)
+        assert get_vm_state(test_vm.vm_name) == 'p'
+
+        # should destroy the vm
+        logging.info("test vm save with with no pause/cont args")
+        test_vm.save(snapshot_file)
+        with pytest.raises(Exception):
+            get_vm_state(test_vm.name)
+
+    def test_vm_pause(self, test_vm):
+        # initialize the VM after previous destruction
+        test_vm.create()
+
+        assert get_vm_state(test_vm.vm_name) != 'p'
+
+        # test-hvm64-example goes to shutdown immediately, we get `--ps--` state during assertion
+
+        # logging.info("testing pause on VM")
+        # test_vm.pause()
+        # assert get_vm_state(test_vm.vm_name) == 'p'
+
+        # manual test shows, xl pause on a paused VM doesn't give any errors but pauses the VM again
+        # requiring the VM be unpaused twice for reaching running state
+
+        # logging.info("testing pause on a paused vm VM")
+        # with pytest.raises(Exception):
+        #     test_vm.pause()
+
+        destroy_vm(test_vm.vm_name)
+
+    def test_vm_restore(self, config, snapshot_file, test_vm):
+        # if snapshot doesn't exist
+        logging.info("test vm restore without snapshot file")
+        with remove_files([snapshot_file]):
+            with pytest.raises(Exception):
+                test_vm.restore(snapshot_path=snapshot_file)
+                assert test_vm.is_running is False
+
+        # if configuration file doesn't exist
+        logging.info("test vm restore without config")
+        with remove_files([config]):
+            with pytest.raises(Exception):
+                test_vm.restore(snapshot_path=snapshot_file)
+                assert test_vm.is_running is False
+
+        # although test-hvm64-example doesn't depend on storage backend
+        # some test like this would have been good where storage backend doesn't exist
+        # and it is trying to restore from vm-1 or vm-0
+        # vm-0 should fail but vm-1 should succeed
+        # if backend.exists_vm(0) is False:
+        #     with pytest.raises(Exception):
+        #         test_vm.restore()
+        #         assert test_vm.is_running is False
+
+        # should not raise any exceptions if everything is fine
+        logging.info("test vm with proper args")
+        test_vm.restore(snapshot_path=snapshot_file)
+        assert get_vm_state(test_vm.vm_name) != 'p'
+
+        destroy_vm(test_vm.vm_name)
+
+        logging.info("test vm with proper args and pause=True")
+        test_vm.restore(snapshot_path=snapshot_file, pause=True)
+        assert get_vm_state(test_vm.vm_name) == 'p'
+
+        logging.info("restoring a restored VM")
+        test_vm.restore(snapshot_path=snapshot_file)
+        # should get the new state
+        assert get_vm_state(test_vm.vm_name) != 'p'
+
+        destroy_vm(test_vm.vm_name)
+
+    def test_vm_destroy(self, test_vm):
+        test_vm.create(pause=True)
+
+        logging.info("test vm destroy")
+        test_vm.destroy()
+        with pytest.raises(Exception):
+            get_vm_state(test_vm.name)
+
+        # should not raise any exception
+        logging.info("test vm destroy on a destroyed VM")
+        test_vm.destroy()
+        assert test_vm.is_running is False