lvm2: add debug logging for all LVM2 command lines

snapm/_snapm.py

@@ -43,6 +43,8 @@
 SNAPM_DEBUG_MOUNTS = 16
 SNAPM_DEBUG_FSDIFF = 32
 SNAPM_DEBUG_PLUGIN = 64
+SNAPM_DEBUG_LVM2 = 128
+SNAPM_DEBUG_LVM2_ERR = 256
 SNAPM_DEBUG_ALL = (
     SNAPM_DEBUG_MANAGER
     | SNAPM_DEBUG_COMMAND
@@ -51,6 +53,8 @@
     | SNAPM_DEBUG_MOUNTS
     | SNAPM_DEBUG_FSDIFF
     | SNAPM_DEBUG_PLUGIN
+    | SNAPM_DEBUG_LVM2
+    | SNAPM_DEBUG_LVM2_ERR
 )
 
 # Snapm debugging subsystem names
@@ -61,6 +65,8 @@
 SNAPM_SUBSYSTEM_MOUNTS = "snapm.mounts"
 SNAPM_SUBSYSTEM_FSDIFF = "snapm.fsdiff"
 SNAPM_SUBSYSTEM_PLUGIN = "snapm.plugin"
+SNAPM_SUBSYSTEM_LVM2 = "snapm.lvm2"
+SNAPM_SUBSYSTEM_LVM2_ERR = "snapm.lvm2err"
 
 _DEBUG_MASK_TO_SUBSYSTEM = {
     SNAPM_DEBUG_MANAGER: SNAPM_SUBSYSTEM_MANAGER,
@@ -70,6 +76,8 @@
     SNAPM_DEBUG_MOUNTS: SNAPM_SUBSYSTEM_MOUNTS,
     SNAPM_DEBUG_FSDIFF: SNAPM_SUBSYSTEM_FSDIFF,
     SNAPM_DEBUG_PLUGIN: SNAPM_SUBSYSTEM_PLUGIN,
+    SNAPM_DEBUG_LVM2: SNAPM_SUBSYSTEM_LVM2,
+    SNAPM_DEBUG_LVM2_ERR: SNAPM_SUBSYSTEM_LVM2_ERR,
 }
 
 _debug_subsystems = set()
@@ -2523,6 +2531,8 @@ def _check_snapm_dir(dirpath: str, mode: int, name: str) -> str:
     "SNAPM_DEBUG_MOUNTS",
     "SNAPM_DEBUG_FSDIFF",
     "SNAPM_DEBUG_PLUGIN",
+    "SNAPM_DEBUG_LVM2",
+    "SNAPM_DEBUG_LVM2_ERR",
     "SNAPM_DEBUG_ALL",
     # Path to runtime directory
     "SNAPM_RUNTIME_DIR",
@@ -2539,6 +2549,8 @@ def _check_snapm_dir(dirpath: str, mode: int, name: str) -> str:
     "SNAPM_SUBSYSTEM_MOUNTS",
     "SNAPM_SUBSYSTEM_FSDIFF",
     "SNAPM_SUBSYSTEM_PLUGIN",
+    "SNAPM_SUBSYSTEM_LVM2",
+    "SNAPM_SUBSYSTEM_LVM2_ERR",
     # Debug logging - legacy interface
     "set_debug_mask",
     "get_debug_mask",

snapm/command.py

@@ -67,6 +67,8 @@
     SNAPM_DEBUG_MOUNTS,
     SNAPM_DEBUG_FSDIFF,
     SNAPM_DEBUG_PLUGIN,
+    SNAPM_DEBUG_LVM2,
+    SNAPM_DEBUG_LVM2_ERR,
     SNAPM_DEBUG_ALL,
     SNAPM_SUBSYSTEM_COMMAND,
     SubsystemFilter,
@@ -2448,6 +2450,8 @@ def set_debug(debug_arg):
         "mounts": SNAPM_DEBUG_MOUNTS,
         "fsdiff": SNAPM_DEBUG_FSDIFF,
         "plugin": SNAPM_DEBUG_PLUGIN,
+        "lvm2": SNAPM_DEBUG_LVM2,
+        "lvm2err": SNAPM_DEBUG_LVM2_ERR,
         "all": SNAPM_DEBUG_ALL,
     }
 

snapm/manager/plugins/lvm2.py

@@ -15,9 +15,15 @@
 from math import floor
 from stat import S_ISBLK
 from time import time
+from shlex import join as shlex_join
 from shutil import which
+import logging
 
 from snapm import (
+    SNAPM_DEBUG_LVM2,
+    SNAPM_SUBSYSTEM_LVM2,
+    SNAPM_SUBSYSTEM_LVM2_ERR,
+    get_debug_mask,
     SnapmInvalidIdentifierError,
     SnapmSizePolicyError,
     SnapmCalloutError,
@@ -48,6 +54,19 @@
     encode_mount_point,
 )
 
+_log = logging.getLogger(__name__)
+
+
+def _log_debug_lvm2(msg, *args, **kwargs):
+    """A wrapper for lvm2 subsystem debug logs."""
+    _log.debug(msg, *args, extra={"subsystem": SNAPM_SUBSYSTEM_LVM2}, **kwargs)
+
+
+def _log_debug_lvm2_err(msg, *args, **kwargs):
+    """A wrapper for lvm2err subsystem debug logs."""
+    _log.debug(msg, *args, extra={"subsystem": SNAPM_SUBSYSTEM_LVM2_ERR}, **kwargs)
+
+
 #: Maximum length for LVM2 LV names
 LVM_MAX_NAME_LEN = 127
 #: Length of extension for LVM2 CoW snapshot LV name
@@ -518,14 +537,26 @@ def _run(
         in ``self._env``.
         """
         kwargs["env"] = self._env | kwargs["env"] if "env" in kwargs else self._env
-        return run(
-            *popenargs,
-            input=input,
-            capture_output=capture_output,
-            timeout=timeout,
-            check=check,
-            **kwargs,
-        )
+        cmd_str = shlex_join(popenargs[0])
+        _log_debug_lvm2("lvm2: %s", cmd_str)
+        try:
+            result = run(
+                *popenargs,
+                input=input,
+                capture_output=capture_output,
+                timeout=timeout,
+                check=check,
+                **kwargs,
+            )
+        except CalledProcessError as err:
+            err_msg = err.stderr.decode("utf8").strip() if err.stderr else ""
+            _log_debug_lvm2("lvm2: %s failed: %s", cmd_str, err_msg)
+            if not get_debug_mask() & SNAPM_DEBUG_LVM2:
+                _log_debug_lvm2_err("lvm2: %s failed: %s", cmd_str, err_msg)
+            raise
+        if capture_output and result.stdout:
+            _log_debug_lvm2("lvm2: output: %s", result.stdout.decode("utf8").strip())
+        return result
 
     def _is_lvm_device(self, device):
         """

tests/test_command.py

@@ -206,7 +206,7 @@ def test_set_debug_list(self):
         from snapm import get_debug_mask, SNAPM_DEBUG_ALL
 
         args = MockArgs()
-        args.debug = "manager,command,report,schedule,mounts,fsdiff,plugin"
+        args.debug = "manager,command,report,schedule,mounts,fsdiff,plugin,lvm2,lvm2err"
         command.set_debug(args.debug)
         self.assertEqual(get_debug_mask(), SNAPM_DEBUG_ALL)