Use python logging infrastructure inside tests

tests/bluechi_test/container.py

@@ -1,6 +1,7 @@
 # SPDX-License-Identifier: LGPL-2.1-or-later
 
 import io
+import logging
 import os
 import time
 import tarfile
@@ -11,6 +12,8 @@
 from bluechi_test.config import BluechiConfig, BluechiNodeConfig, BluechiControllerConfig
 from bluechi_test.util import read_file, get_random_name
 
+logger = logging.getLogger(__name__)
+
 
 class BluechiContainer():
 
@@ -80,8 +83,8 @@ def copy_systemd_service(self, service_file_name: str, source_dir: str, target_d
         source_path = os.path.join(source_dir, service_file_name)
         content = read_file(source_path)
 
-        print(f"Copy local systemd service '{source_path}' to container path '{target_dir}' with content:")
-        print(f"{content}\n")
+        logger.debug(f"Copy local systemd service '{source_path}' to container path '{target_dir}'\
+             with content:\n{content}")
         self.create_file(target_dir, service_file_name, content)
         self.systemctl_daemon_reload()
 
@@ -110,8 +113,8 @@ def wait_for_unit_state_to_be(self, unit_name: str, expected_state: str, timeout
             if latest_state == expected_state:
                 return True
 
-        print(f"Timeout while waiting for {unit_name} to reach state {expected_state}. \
-              Latest state: {latest_state}")
+        logger.debug(f"Timeout while waiting for '{unit_name}' to reach state '{expected_state}'. \
+              Latest state: '{latest_state}'")
         return False
 
     def run_python(self, python_script_path: str) -> \
@@ -123,7 +126,10 @@ def run_python(self, python_script_path: str) -> \
         self.create_file(target_file_dir, target_file_name, content)
 
         target_file_path = os.path.join(target_file_dir, target_file_name)
+        logger.debug(f"Executing python script '{target_file_path}'")
         result, output = self.exec_run(f'python3 {target_file_path}')
+        logger.debug(f"Execute python script '{target_file_path}' finished with result '{result}' \
+            and output:\n{output}")
         try:
             os.remove(target_file_path)
         finally:
@@ -165,36 +171,46 @@ def copy_systemd_service(self, service_file_name: str, source_dir: str, target_d
         self.wait_for_bluechi()
 
     def start_unit(self, node_name: str, unit_name: str) -> None:
-        print(f"Starting unit {unit_name} on node {node_name}")
+        logger.debug(f"Starting unit '{unit_name}' on node '{node_name}'")
 
         result, output = self.exec_run(f"bluechictl start {node_name} {unit_name}")
+        logger.debug(f"Start unit '{unit_name}' on node '{node_name}' finished with result '{result}' \
+            and output:\n{output}")
         if result != 0:
             raise Exception(f"Failed to start service {unit_name} on node {node_name}: {output}")
 
     def stop_unit(self, node_name: str, unit_name: str) -> None:
-        print(f"Stopping unit {unit_name} on node {node_name}")
+        logger.debug(f"Stopping unit '{unit_name}' on node '{node_name}'")
 
         result, output = self.exec_run(f"bluechictl stop {node_name} {unit_name}")
+        logger.debug(f"Stop unit '{unit_name}' on node '{node_name}' finished with result '{result}' \
+            and output:\n{output}")
         if result != 0:
             raise Exception(f"Failed to start service {unit_name} on node {node_name}: {output}")
 
     def enable_unit(self, node_name: str, unit_name: str) -> None:
-        print(f"Enabling unit {unit_name} on node {node_name}")
+        logger.debug(f"Enabling unit '{unit_name}' on node '{node_name}'")
 
         result, output = self.exec_run(f"bluechictl enable {node_name} {unit_name}")
+        logger.debug(f"Enable unit '{unit_name}' on node '{node_name}' finished with result '{result}' \
+            and output:\n{output}")
         if result != 0:
             raise Exception(f"Failed to enable service {unit_name} on node {node_name}: {output}")
 
     def freeze_unit(self, node_name: str, unit_name: str) -> None:
-        print(f"Freezing unit {unit_name} on node {node_name}")
+        logger.debug(f"Freezing unit {unit_name} on node {node_name}")
 
         result, output = self.exec_run(f"bluechictl freeze {node_name} {unit_name}")
+        logger.debug(f"Freeze unit '{unit_name}' on node '{node_name}' finished with result '{result}' \
+            and output:\n{output}")
         if result != 0:
             raise Exception(f"Failed to freeze service {unit_name} on node {node_name}: {output}")
 
     def thaw_unit(self, node_name: str, unit_name: str) -> None:
-        print(f"Thawing unit {unit_name} on node {node_name}")
+        logger.debug(f"Thawing unit {unit_name} on node {node_name}")
 
         result, output = self.exec_run(f"bluechictl thaw {node_name} {unit_name}")
+        logger.debug(f"Thaw unit '{unit_name}' on node '{node_name}' finished with result '{result}' \
+            and output:\n{output}")
         if result != 0:
             raise Exception(f"Failed to thaw service {unit_name} on node {node_name}: {output}")

tests/bluechi_test/test.py

@@ -1,5 +1,6 @@
 # SPDX-License-Identifier: LGPL-2.1-or-later
 
+import logging
 import traceback
 
 from podman import PodmanClient
@@ -9,6 +10,8 @@
 from bluechi_test.config import BluechiControllerConfig, BluechiNodeConfig
 from bluechi_test.container import BluechiNodeContainer, BluechiControllerContainer
 
+logger = logging.getLogger(__name__)
+
 
 class BluechiTest():
 
@@ -45,8 +48,8 @@ def setup(self) -> Tuple[bool, Tuple[BluechiControllerContainer, Dict[str, Bluec
         ctrl_container: BluechiControllerContainer = None
         node_container: Dict[str, BluechiNodeContainer] = dict()
         try:
-            print(
-                f"Starting container for bluechi-controller with config:\n{self.bluechi_controller_config.serialize()}")
+            logger.debug(f"Starting container for bluechi-controller with config:\
+                \n{self.bluechi_controller_config.serialize()}")
 
             c = self.podman_client.containers.run(
                 name=self.bluechi_controller_config.name,
@@ -61,7 +64,7 @@ def setup(self) -> Tuple[bool, Tuple[BluechiControllerContainer, Dict[str, Bluec
             ctrl_container.exec_run('systemctl start bluechi')
 
             for cfg in self.bluechi_node_configs:
-                print(f"Starting container bluechi-node '{cfg.node_name}' with config:\n{cfg.serialize()}")
+                logger.debug(f"Starting container bluechi-node '{cfg.node_name}' with config:\n{cfg.serialize()}")
 
                 c = self.podman_client.containers.run(
                     name=cfg.node_name,
@@ -78,12 +81,12 @@ def setup(self) -> Tuple[bool, Tuple[BluechiControllerContainer, Dict[str, Bluec
 
         except Exception as ex:
             success = False
-            print(f"Failed to setup bluechi container: {ex}")
+            logger.debug(f"Failed to setup bluechi container: {ex}")
 
         return (success, (ctrl_container, node_container))
 
     def gather_logs(self, ctrl: BluechiControllerContainer, nodes: Dict[str, BluechiNodeContainer]):
-        print("Collecting logs from all containers...")
+        logger.debug("Collecting logs from all containers...")
 
         if ctrl is not None:
             ctrl.gather_journal_logs(self.tmt_test_data_dir)
@@ -94,15 +97,15 @@ def gather_logs(self, ctrl: BluechiControllerContainer, nodes: Dict[str, Bluechi
         self.gather_test_executor_logs()
 
     def gather_test_executor_logs(self) -> None:
-        print("Collecting logs from test executor...")
+        logger.debug("Collecting logs from test executor...")
         log_file = f"{self.tmt_test_data_dir}/journal-test_executor.log"
         try:
             Command(f"journalctl --no-pager > {log_file}").run()
         except Exception as ex:
-            print(f"Failed to gather test executor journal: {ex}")
+            logger.debug(f"Failed to gather test executor journal: {ex}")
 
     def teardown(self, ctrl: BluechiControllerContainer, nodes: Dict[str, BluechiNodeContainer]):
-        print("Stopping and removing all container...")
+        logger.debug("Stopping and removing all container...")
 
         if ctrl is not None:
             ctrl.cleanup()

tests/bluechi_test/util.py

@@ -1,11 +1,14 @@
 # SPDX-License-Identifier: LGPL-2.1-or-later
 
+import logging
 import random
 import string
 import socket
 
 from typing import Union
 
+logger = logging.getLogger(__name__)
+
 
 def read_file(local_file: str) -> Union[str, None]:
     content = None
@@ -21,8 +24,8 @@ def get_primary_ip() -> str:
         # connect to an arbitrary address
         s.connect(("254.254.254.254", 1))
         ip = s.getsockname()[0]
-    except Exception as ex:
-        print(f"Failed to get IP, falling back to localhost. Exception: {ex}")
+    except Exception:
+        logging.exception("Failed to get IP, falling back to localhost.")
         ip = "127.0.0.1"
     finally:
         s.close()

tests/tests/main.fmf

@@ -1 +1,6 @@
-test: pytest -svv --confcutdir=../../../
+test: |
+    pytest -svv \
+    --confcutdir=../../../ \
+    --log-cli-level=DEBUG \
+    --log-cli-date-format="%Y-%m-%d %H:%M:%S%z" \
+    --log-cli-format="%(asctime)s,%(msecs)03d %(levelname)-7s [%(name)s] %(message)s (%(module)s:%(lineno)d)"