test: add debug logging of runcmd calls

1 files changed, 16 insertions, 27 deletions

diff --git a/runcmd.py b/runcmd.py
index b67c6bb..631d8c0 100644
--- a/runcmd.py
+++ b/runcmd.py
@@ -1,10 +1,16 @@
 # Some step implementations for running commands and capturing the result.
 
+import logging
+import os
 import subprocess
 
 
 # Run a command, capture its stdout, stderr, and exit code in context.
 def runcmd(ctx, argv, **kwargs):
+    logging.debug(f"Running program")
+    logging.debug(f"  cwd={os.getcwd()}")
+    logging.debug(f"  argv={argv}")
+    logging.debug(f"  kwargs={argv}")
     p = subprocess.Popen(argv, stdout=subprocess.PIPE, stderr=subprocess.PIPE, **kwargs)
     stdout, stderr = p.communicate("")
     ctx["argv"] = argv
@@ -15,25 +21,16 @@ def runcmd(ctx, argv, **kwargs):
 
 # Check that latest exit code captured by runcmd was a specific one.
 def exit_code_is(ctx, wanted):
-    if ctx.get("exit") != wanted:
-        print("context:", ctx.as_dict())
+    logging.debug(f"Verifying exit code is {wanted} (it is {ctx.get('exit')})")
     assert_eq(ctx.get("exit"), wanted)
 
 
 # Check that latest exit code captured by runcmd was not a specific one.
 def exit_code_is_not(ctx, unwanted):
-    if ctx.get("exit") == wanted:
-        print("context:", ctx.as_dict())
+    logging.debug(f"Verifying exit code is NOT {unwanted} (it is {ctx.get('exit')})")
     assert_ne(ctx.get("exit"), wanted)
 
 
-# Check that latest exit code captured by runcmd was not a specific one.
-def exit_code_is_not(ctx, unwanted):
-    if ctx.get("exit") == unwanted:
-        print("context:", ctx.as_dict())
-    assert_ne(ctx.get("exit"), unwanted)
-
-
 # Check that latest exit code captured by runcmd was zero.
 def exit_code_zero(ctx):
     exit_code_is(ctx, 0)
@@ -46,39 +43,31 @@ def exit_code_nonzero(ctx):
 
 # Check that stdout of latest runcmd contains a specific string.
 def stdout_contains(ctx, pattern=None):
+    logging.debug(f"Verifying stdout contains {pattern}")
+    logging.debug(f"  stdout is {ctx.get('stdout', '')})")
     stdout = ctx.get("stdout", "")
-    if pattern not in stdout:
-        print("pattern:", repr(pattern))
-        print("stdout:", repr(stdout))
-        print("ctx:", ctx.as_dict())
     assert_eq(pattern in stdout, True)
 
 
 # Check that stdout of latest runcmd does not contain a specific string.
 def stdout_does_not_contain(ctx, pattern=None):
+    logging.debug(f"Verifying stdout does NOT contain {pattern}")
+    logging.debug(f"  stdout is {ctx.get('stdout', '')})")
     stdout = ctx.get("stdout", "")
-    if pattern in stdout:
-        print("pattern:", repr(pattern))
-        print("stdout:", repr(stdout))
-        print("ctx:", ctx.as_dict())
     assert_eq(pattern not in stdout, True)
 
 
 # Check that stderr of latest runcmd does contains a specific string.
 def stderr_contains(ctx, pattern=None):
+    logging.debug(f"Verifying stderr contains {pattern}")
+    logging.debug(f"  stderr is {ctx.get('stderr', '')})")
     stderr = ctx.get("stderr", "")
-    if pattern not in stderr:
-        print("pattern:", repr(pattern))
-        print("stderr:", repr(stderr))
-        print("ctx:", ctx.as_dict())
     assert_eq(pattern in stderr, True)
 
 
 # Check that stderr of latest runcmd does not contain a specific string.
 def stderr_does_not_contain(ctx, pattern=None):
+    logging.debug(f"Verifying stderr does NOT contain {pattern}")
+    logging.debug(f"  stderr is {ctx.get('stderr', '')})")
     stderr = ctx.get("stderr", "")
-    if pattern not in stderr:
-        print("pattern:", repr(pattern))
-        print("stderr:", repr(stderr))
-        print("ctx:", ctx.as_dict())
     assert_eq(pattern not in stderr, True)