Log shell commands in machinery

CERT-Polska · Sep 28, 2023 · 585ac86 · 585ac86
1 parent a4e53fc
commit 585ac86
Show file tree

Hide file tree

Showing 5 changed files with 84 additions and 54 deletions.
diff --git a/draklib/draklib/machinery/networking.py b/draklib/draklib/machinery/networking.py
@@ -8,13 +8,14 @@
 
 from ..config import Configuration
 from .xen import get_domid_from_name
+from .subprocess import check_output, run, Popen
 
 log = logging.getLogger(__name__)
 
 
 def find_default_interface():
     routes = (
-        subprocess.check_output(
+        check_output(
             "ip route show default", shell=True, stderr=subprocess.STDOUT
         )
         .decode("ascii")
@@ -33,7 +34,7 @@ def find_default_interface():
 
 def check_networking_prerequisites() -> None:
     try:
-        subprocess.check_output("brctl show", shell=True)
+        check_output("brctl show", shell=True)
     except subprocess.CalledProcessError:
         raise RuntimeError(
             "Failed to execute brctl show. Make sure you have bridge-utils installed."
@@ -48,7 +49,7 @@ def check_networking_prerequisites() -> None:
 
 def iptable_rule_exists(rule: str) -> bool:
     try:
-        subprocess.check_output(
+        check_output(
             f"iptables -C {rule}", shell=True, stderr=subprocess.DEVNULL
         )
         return True
@@ -63,7 +64,7 @@ def iptable_rule_exists(rule: str) -> bool:
 
 def add_iptable_rule(rule: str) -> None:
     if not iptable_rule_exists(rule):
-        subprocess.check_output(f"iptables -A {rule}", shell=True)
+        check_output(f"iptables -A {rule}", shell=True)
 
 
 def del_iptable_rule(rule: str) -> None:
@@ -72,13 +73,13 @@ def del_iptable_rule(rule: str) -> None:
 
     while not all_cleared:
         if iptable_rule_exists(rule):
-            subprocess.check_output(f"iptables -D {rule}", shell=True)
+            check_output(f"iptables -D {rule}", shell=True)
         else:
             all_cleared = True
 
 
 def list_iptables_rules() -> List[str]:
-    return subprocess.check_output("iptables -S", shell=True, text=True).split("\n")
+    return check_output("iptables -S", shell=True, text=True).split("\n")
 
 
 def vif_from_vm_name(vm_name: str) -> str:
@@ -92,11 +93,11 @@ def bridge_from_vm_name(vm_name: str) -> str:
 
 def start_tcpdump_collector(vm_name: str, outdir: Path) -> subprocess.Popen:
     try:
-        subprocess.check_output("tcpdump --version", shell=True)
+        check_output("tcpdump --version", shell=True)
     except subprocess.CalledProcessError:
         raise RuntimeError("Failed to start tcpdump")
 
-    return subprocess.Popen(
+    return Popen(
         ["tcpdump", "-i", vif_from_vm_name(vm_name), "-w", str(outdir / "dump.pcap")]
     )
 
@@ -105,7 +106,7 @@ def start_dnsmasq(
     config: Configuration, vm_id: int, dns_server: str, background=False
 ) -> Optional[subprocess.Popen]:
     try:
-        subprocess.check_output("dnsmasq --version", shell=True)
+        check_output("dnsmasq --version", shell=True)
     except subprocess.CalledProcessError:
         raise RuntimeError("Failed to start dnsmasq")
 
@@ -133,7 +134,7 @@ def start_dnsmasq(
     dhcp_first_addr = config.ip_from_vm_id(vm_id, host_id=100)
     dhcp_last_addr = config.ip_from_vm_id(vm_id, host_id=200)
 
-    return subprocess.Popen(
+    return Popen(
         [
             "dnsmasq",
             "--no-daemon" if not background else "",
@@ -168,7 +169,7 @@ def stop_dnsmasq(config: Configuration, vm_id: int) -> None:
 
 
 def interface_exists(iface: str) -> bool:
-    proc = subprocess.run(["ip", "link", "show", iface], capture_output=True)
+    proc = run(["ip", "link", "show", iface], capture_output=True)
     return proc.returncode == 0
 
 
@@ -182,7 +183,7 @@ def setup_vm_network(
     vm_name = config.get_vm_name(vm_id)
     bridge_name = bridge_from_vm_name(vm_name)
     try:
-        subprocess.check_output(
+        check_output(
             f"brctl addbr {bridge_name}", stderr=subprocess.STDOUT, shell=True
         )
         log.info(f"Created bridge {bridge_name}")
@@ -194,11 +195,11 @@ def setup_vm_network(
             raise Exception(f"Failed to create bridge {bridge_name}.")
     else:
         gateway_ip = config.ip_from_vm_id(vm_id, host_id=1)
-        subprocess.run(
+        run(
             f"ip addr add {gateway_ip}/24 dev {bridge_name}", shell=True, check=True
         )
 
-    subprocess.run(f"ip link set dev {bridge_name} up", shell=True, check=True)
+    run(f"ip link set dev {bridge_name} up", shell=True, check=True)
     log.info(f"Bridge {bridge_name} is up")
 
     add_iptable_rule(
@@ -229,7 +230,7 @@ def delete_vm_network(config: Configuration, vm_id: int) -> None:
     vm_name = config.get_vm_name(vm_id)
     bridge_name = bridge_from_vm_name(vm_name)
     try:
-        subprocess.check_output(
+        check_output(
             f"ip link set dev {bridge_name} down", shell=True, stderr=subprocess.STDOUT
         )
         log.info(f"Bridge {bridge_name} is down")
@@ -240,7 +241,7 @@ def delete_vm_network(config: Configuration, vm_id: int) -> None:
             log.debug(e.output)
             raise Exception(f"Couldn't deactivate {bridge_name} bridge")
     else:
-        subprocess.run(
+        run(
             f"brctl delbr {bridge_name}", stderr=subprocess.STDOUT, shell=True
         )
         log.info(f"Deleted {bridge_name} bridge")

diff --git a/draklib/draklib/machinery/storage.py b/draklib/draklib/machinery/storage.py
@@ -11,6 +11,8 @@
 from ..config import Configuration
 from ..util import ensure_delete
 
+from .subprocess import check_output, run
+
 log = logging.getLogger(__name__)
 
 
@@ -82,7 +84,7 @@ def __init__(self, config: Configuration):
     def check_tools():
         """Verify existence of zfs command utility"""
         try:
-            subprocess.check_output("zfs -?", shell=True)
+            check_output("zfs -?", shell=True)
         except subprocess.CalledProcessError:
             raise RuntimeError(
                 "Failed to execute zfs command. "
@@ -92,7 +94,7 @@ def check_tools():
     def initialize_vm0_volume(self, disk_size: str):
         vm0_vol = shlex.quote(os.path.join(self.zfs_tank_name, "vm-0"))
         try:
-            subprocess.check_output(
+            check_output(
                 f"zfs destroy -Rfr {vm0_vol}", stderr=subprocess.STDOUT, shell=True
             )
         except subprocess.CalledProcessError as exc:
@@ -101,7 +103,7 @@ def initialize_vm0_volume(self, disk_size: str):
                     f"Failed to destroy the existing ZFS volume {vm0_vol}."
                 )
         try:
-            subprocess.check_output(
+            check_output(
                 " ".join(
                     [
                         "zfs",
@@ -119,7 +121,7 @@ def initialize_vm0_volume(self, disk_size: str):
 
     def snapshot_vm0_volume(self):
         snap_name = shlex.quote(os.path.join(self.zfs_tank_name, "vm-0@booted"))
-        subprocess.check_output(f"zfs snapshot {snap_name}", shell=True)
+        check_output(f"zfs snapshot {snap_name}", shell=True)
 
     def get_vm_disk_path(self, vm_id: int) -> str:
         return f"phy:/dev/zvol/{self.zfs_tank_name}/vm-{vm_id},hda,w"
@@ -129,7 +131,7 @@ def rollback_vm_storage(self, vm_id: int):
         vm_snap = os.path.join(self.zfs_tank_name, f"vm-{vm_id}@booted")
 
         if not os.path.exists(vm_zvol):
-            subprocess.run(
+            run(
                 [
                     "zfs",
                     "clone",
@@ -151,30 +153,30 @@ def rollback_vm_storage(self, vm_id: int):
                     "zfs clone command."
                 )
 
-            subprocess.run(["zfs", "snapshot", vm_snap], check=True)
+            run(["zfs", "snapshot", vm_snap], check=True)
 
-        subprocess.run(["zfs", "rollback", vm_snap], check=True)
+        run(["zfs", "rollback", vm_snap], check=True)
 
     def get_vm0_snapshot_time(self):
         base_snap = shlex.quote(os.path.join(self.zfs_tank_name, "vm-0@booted"))
-        out = subprocess.check_output(
+        out = check_output(
             f"zfs get -H -p -o value creation {base_snap}", shell=True
         )
         ts = int(out.decode("ascii").strip())
         return ts
 
     def export_vm0(self, file):
         with open(file, "wb") as snapshot_file:
-            subprocess.run(
+            run(
                 ["zfs", "send", f"{self.zfs_tank_name}/vm-0@booted"],
                 check=True,
                 stdout=snapshot_file,
             )
 
     def import_vm0(self, file):
-        subprocess.run(["zfs", "create", self.zfs_tank_name], check=True)
+        run(["zfs", "create", self.zfs_tank_name], check=True)
         with open(file, "rb") as snapshot_file:
-            subprocess.run(
+            run(
                 ["zfs", "recv", f"{self.zfs_tank_name}/vm-0@booted"],
                 check=True,
                 stdin=snapshot_file,
@@ -184,7 +186,7 @@ def delete_vm_volume(self, vm_id: int):
         vm_id_vol = os.path.join(self.zfs_tank_name, f"vm-{vm_id}")
         try:
             log.info(f"Deleting zfs volume {vm_id_vol}")
-            subprocess.check_output(
+            check_output(
                 ["zfs", "destroy", "-Rfr", vm_id_vol], stderr=subprocess.STDOUT
             )
         except subprocess.CalledProcessError as exc:
@@ -194,7 +196,7 @@ def delete_vm_volume(self, vm_id: int):
     def delete_zfs_tank(self):
         try:
             log.info("Deleting zfs tank")
-            subprocess.run(
+            run(
                 ["zfs", "destroy", "-r", f"{self.zfs_tank_name}"], check=True
             )
         except subprocess.CalledProcessError as exc:
@@ -213,7 +215,7 @@ def __init__(self, config: Configuration):
     def check_tools():
         """Verify existence of qemu-img"""
         try:
-            subprocess.check_output("qemu-img --version", shell=True)
+            check_output("qemu-img --version", shell=True)
         except subprocess.CalledProcessError:
             raise RuntimeError(
                 "Failed to determine qemu-img version. "
@@ -222,7 +224,7 @@ def check_tools():
 
     def initialize_vm0_volume(self, disk_size: str):
         try:
-            subprocess.check_output(
+            check_output(
                 " ".join(
                     [
                         "qemu-img",
@@ -251,7 +253,7 @@ def rollback_vm_storage(self, vm_id: int):
         vm0_path = self.volume_dir / "vm-0.img"
         volume_path.unlink(missing_ok=True)
 
-        subprocess.run(
+        run(
             [
                 "qemu-img",
                 "create",
@@ -296,7 +298,7 @@ def __init__(self, config: Configuration):
     def check_tools(self):
         """Verify existence of lvm command utility"""
         try:
-            subprocess.run(
+            run(
                 ["vgs", self.lvm_volume_group], check=True, stdout=subprocess.DEVNULL
             )
         except subprocess.CalledProcessError:
@@ -313,7 +315,7 @@ def initialize_vm0_volume(self, disk_size: str):
         """
         try:
             log.info("Deleting existing logical volume and snapshot")
-            subprocess.check_output(
+            check_output(
                 [
                     "lvremove",
                     "-v",
@@ -330,7 +332,7 @@ def initialize_vm0_volume(self, disk_size: str):
                 )
         try:
             log.info("Creating new volume vm-0")
-            subprocess.run(
+            run(
                 [
                     "lvcreate",
                     "-y",
@@ -350,12 +352,12 @@ def snapshot_vm0_volume(self):
         # vm-0 is the original disk being treated as a snapshot
         # vm-0-snap is being created just for the access time
         # of the change in vm snapshot
-        subprocess.run(
+        run(
             ["lvremove", f"{self.lvm_volume_group}/vm-0-snap"],
             stderr=subprocess.DEVNULL,
         )
         try:
-            subprocess.check_output(
+            check_output(
                 [
                     "lvcreate",
                     "-s",
@@ -385,7 +387,7 @@ def rollback_vm_storage(self, vm_id: int):
         log.info(f"Rolling back changes to vm-{vm_id} disk")
         if os.path.exists(vm_id_vol):
             try:
-                subprocess.check_output(
+                check_output(
                     [
                         "lvremove",
                         "-v",
@@ -403,7 +405,7 @@ def rollback_vm_storage(self, vm_id: int):
                 )
 
         try:
-            subprocess.check_output(
+            check_output(
                 [
                     "lvcreate",
                     "-s",
@@ -422,7 +424,7 @@ def rollback_vm_storage(self, vm_id: int):
     def get_vm0_snapshot_time(self):
         """Get UNIX timestamp of when vm-0 snapshot was last modified"""
 
-        p = subprocess.run(
+        p = run(
             ["lvs", "-o", "lv_name,lv_time", "--reportformat", "json"],
             capture_output=True,
             check=True,
@@ -446,7 +448,7 @@ def export_vm0(self, path: str):
         """Export vm-0 disk into a file (symmetric to import_vm0)"""
         # As dd copies empty spaces also
         # Should we use compressions in this? Will it have any issues while importing?
-        subprocess.run(
+        run(
             [
                 "dd",
                 f"if=/dev/{self.lvm_volume_group}/vm-0",
@@ -459,7 +461,7 @@ def export_vm0(self, path: str):
 
     def import_vm0(self, path: str):
         """Import vm-0 disk from a file (symmetric to export_vm0)"""
-        subprocess.run(
+        run(
             [
                 "dd",
                 f"of=/dev/{self.lvm_volume_group}/vm-0",
@@ -472,7 +474,7 @@ def import_vm0(self, path: str):
 
     def delete_vm_volume(self, vm_id: str):
         try:
-            subprocess.check_output(
+            check_output(
                 [
                     "lvremove",
                     "-v",

diff --git a/draklib/draklib/machinery/subprocess.py b/draklib/draklib/machinery/subprocess.py
@@ -0,0 +1,24 @@
+"""
+Subprocess with logging
+"""
+import functools
+import logging
+import subprocess
+from typing import Any, Callable, TypeVar
+
+log = logging.getLogger(__name__)
+
+F = TypeVar("F", bound=Callable[..., Any])
+
+
+def decorate_with_logger(fn: F) -> F:
+    @functools.wraps(fn)
+    def wrapper(*args, **kwargs):
+        log.debug(f"Running shell command '{args[0]}'")
+        return fn(*args, **kwargs)
+    return wrapper
+
+
+check_output = decorate_with_logger(subprocess.check_output)
+run = decorate_with_logger(subprocess.run)
+Popen = decorate_with_logger(subprocess.Popen)