diff --git a/draklib/draklib/machinery/networking.py b/draklib/draklib/machinery/networking.py
index c0e8d16d4..7697476d4 100644
--- 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
index 1bbdc3ee4..f8f7281a9 100644
--- 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,13 +153,13 @@ 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())
@@ -165,16 +167,16 @@ def get_vm0_snapshot_time(self):
 
     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
new file mode 100644
index 000000000..c78874b77
--- /dev/null
+++ 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)
diff --git a/draklib/draklib/machinery/vm.py b/draklib/draklib/machinery/vm.py
index 4ae6a7d67..b77f3497e 100644
--- a/draklib/draklib/machinery/vm.py
+++ b/draklib/draklib/machinery/vm.py
@@ -10,6 +10,8 @@
 from .networking import delete_vm_network, setup_vm_network, start_dnsmasq, stop_dnsmasq
 from .storage import get_storage_backend
 from .xen import eject_cd, insert_cd
+from .subprocess import check_output, run
+
 
 log = logging.getLogger(__name__)
 
@@ -121,13 +123,13 @@ def create(
         args += [str(vm_config_path)]
         log.info(f"Creating VM {self.vm_name}")
         try:
-            subprocess.run(args, check=True)
+            run(args, check=True)
         except subprocess.CalledProcessError:
             raise VMError(f"Failed to launch VM {self.vm_name}", vm_name=self.vm_name)
 
     def pause(self):
         try:
-            subprocess.run(
+            run(
                 ["xl", "pause", self.vm_name],
                 check=True,
             )
@@ -136,7 +138,7 @@ def pause(self):
 
     def unpause(self):
         try:
-            subprocess.run(
+            run(
                 ["xl", "unpause", self.vm_name],
                 check=True,
             )
@@ -153,7 +155,7 @@ def save(self, snapshot_path: Path = None, destroy_after=False):
         logging.info(f"Saving VM {self.vm_name}")
         try:
             # We want to keep it running after saving
-            subprocess.run(
+            run(
                 args,
                 check=True,
             )
@@ -176,13 +178,13 @@ def restore(self, snapshot_path=None, paused=False):
         logging.info(f"Restoring VM {self.vm_name}")
         try:
             # We want to keep it running after saving
-            subprocess.run(args, check=True)
+            run(args, check=True)
         except subprocess.CalledProcessError:
             raise VMError(f"Failed to restore VM {self.vm_name}", vm_name=self.vm_name)
 
     def destroy(self):
         try:
-            subprocess.run(
+            run(
                 ["xl", "destroy", self.vm_name],
                 check=True,
             )
@@ -213,7 +215,7 @@ def make_unattended_iso(xml_path, iso_path):
                 fw.write(fr.read())
 
         try:
-            subprocess.check_output(
+            check_output(
                 [
                     "genisoimage",
                     "-o",
diff --git a/draklib/draklib/machinery/xen.py b/draklib/draklib/machinery/xen.py
index fff993275..f7c149b56 100644
--- a/draklib/draklib/machinery/xen.py
+++ b/draklib/draklib/machinery/xen.py
@@ -1,13 +1,14 @@
 import subprocess
+from .subprocess import check_output, run
 
 
 def get_domid_from_name(vm_name: str) -> int:
-    output = subprocess.check_output(["xl", "domid", vm_name], text=True)
+    output = check_output(["xl", "domid", vm_name], text=True)
     return int(output.strip())
 
 
 def get_xl_info():
-    xl_info_out = subprocess.check_output(["xl", "info"], text=True)
+    xl_info_out = check_output(["xl", "info"], text=True)
     xl_info_lines = xl_info_out.strip().split("\n")
 
     cfg = {}
@@ -21,8 +22,8 @@ def get_xl_info():
 
 
 def eject_cd(domain, drive):
-    subprocess.run(["xl", "cd-eject", domain, drive], check=True)
+    run(["xl", "cd-eject", domain, drive], check=True)
 
 
 def insert_cd(domain, drive, iso):
-    subprocess.run(["xl", "cd-insert", domain, drive, iso], check=True)
+    run(["xl", "cd-insert", domain, drive, iso], check=True)