test: make Python backend logging nicer

Mostly this avoids writing very long lines. Long strings are broken
into multiple lines, logged separately. Various other values are also
logged as multiple log lines as well.

5 files changed, 114 insertions, 30 deletions

diff --git a/share/python/lib/files.py b/share/python/lib/files.py
index d3b96fc..66ec4d0 100644
--- a/share/python/lib/files.py
+++ b/share/python/lib/files.py
@@ -160,20 +160,25 @@ def files_mtime_is_ancient(ctx, filename=None):
 
 
 def files_remember_metadata(ctx, filename=None):
+    log_value = globals()["log_value"]
+
     meta = _files_remembered(ctx)
     meta[filename] = _files_get_metadata(filename)
     logging.debug("files_remember_metadata:")
-    logging.debug(f"  meta: {meta}")
-    logging.debug(f"  ctx: {ctx}")
+    log_value("meta", 1, meta)
+    log_value("ctx", 1, ctx.as_dict())
 
 
 # Check that current metadata of a file is as stored in the context.
 def files_has_remembered_metadata(ctx, filename=None):
     assert_eq = globals()["assert_eq"]
+    log_value = globals()["log_value"]
+
     meta = _files_remembered(ctx)
     logging.debug("files_has_remembered_metadata:")
-    logging.debug(f"  meta: {meta}")
-    logging.debug(f"  ctx: {ctx}")
+    log_value("meta", 1, meta)
+    log_value("ctx", 1, ctx.as_dict())
+
     assert_eq(meta[filename], _files_get_metadata(filename))
 
 
diff --git a/share/python/lib/runcmd.py b/share/python/lib/runcmd.py
index 1eddb9e..90ab890 100644
--- a/share/python/lib/runcmd.py
+++ b/share/python/lib/runcmd.py
@@ -48,7 +48,7 @@ def runcmd_get_argv(ctx):
 # stdout, stderr, and exit code are stored in the "_runcmd" namespace in the
 # ctx context.
 def runcmd_run(ctx, argv, **kwargs):
-    log_dict = globals()["log_dict"]
+    log_value = globals()["log_value"]
 
     ns = ctx.declare("_runcmd")
 
@@ -68,10 +68,10 @@ def runcmd_run(ctx, argv, **kwargs):
     kwargs["stdout"] = subprocess.PIPE
     kwargs["stderr"] = subprocess.PIPE
 
-    logging.debug(f"runcmd_run")
-    log_dict(dict(enumerate(argv)), "argv", level=1)
-    log_dict(env, "env:", level=1)
-    log_dict(kwargs, "kwargs:", level=1)
+    logging.debug(f"runcmd_run: running command")
+    log_value("argv", 1, dict(enumerate(argv)))
+    log_value("env", 1, env)
+    log_value("kwargs:", 1, kwargs)
 
     p = subprocess.Popen(argv, env=env, **kwargs)
     stdout, stderr = p.communicate("")
@@ -83,7 +83,7 @@ def runcmd_run(ctx, argv, **kwargs):
     ns["stderr"] = stderr.decode("utf-8")
     ns["exit"] = p.returncode
 
-    log_dict(ns.as_dict(), "ns", level=1)
+    log_value("ns", 1, ns.as_dict())
 
 
 # Step: prepend srcdir to PATH whenever runcmd runs a command.
@@ -179,19 +179,35 @@ def runcmd_stderr_isnt(ctx, text=None):
 
 def _runcmd_output_is(actual, wanted):
     assert_eq = globals()["assert_eq"]
+    log_lines = globals()["log_lines"]
+    indent = " " * 4
+
     wanted = bytes(wanted, "utf8").decode("unicode_escape")
     logging.debug("_runcmd_output_is:")
-    logging.debug(f"  actual: {actual!r}")
-    logging.debug(f"  wanted: {wanted!r}")
+
+    logging.debug(f"  actual:")
+    log_lines(indent, actual)
+
+    logging.debug(f"  wanted:")
+    log_lines(indent, wanted)
+
     assert_eq(actual, wanted)
 
 
 def _runcmd_output_isnt(actual, wanted):
     assert_ne = globals()["assert_ne"]
+    log_lines = globals()["log_lines"]
+    indent = " " * 4
+
     wanted = bytes(wanted, "utf8").decode("unicode_escape")
     logging.debug("_runcmd_output_isnt:")
-    logging.debug(f"  actual: {actual!r}")
-    logging.debug(f"  wanted: {wanted!r}")
+
+    logging.debug(f"  actual:")
+    log_lines(indent, actual)
+
+    logging.debug(f"  wanted:")
+    log_lines(indent, wanted)
+
     assert_ne(actual, wanted)
 
 
@@ -213,19 +229,35 @@ def runcmd_stderr_doesnt_contain(ctx, text=None):
 
 def _runcmd_output_contains(actual, wanted):
     assert_eq = globals()["assert_eq"]
+    log_lines = globals()["log_lines"]
+    indent = " " * 4
+
     wanted = bytes(wanted, "utf8").decode("unicode_escape")
     logging.debug("_runcmd_output_contains:")
-    logging.debug(f"  actual: {actual!r}")
-    logging.debug(f"  wanted: {wanted!r}")
+
+    logging.debug(f"  actual:")
+    log_lines(indent, actual)
+
+    logging.debug(f"  wanted:")
+    log_lines(indent, wanted)
+
     assert_eq(wanted in actual, True)
 
 
 def _runcmd_output_doesnt_contain(actual, wanted):
     assert_ne = globals()["assert_ne"]
+    log_lines = globals()["log_lines"]
+    indent = " " * 4
+
     wanted = bytes(wanted, "utf8").decode("unicode_escape")
     logging.debug("_runcmd_output_doesnt_contain:")
-    logging.debug(f"  actual: {actual!r}")
-    logging.debug(f"  wanted: {wanted!r}")
+
+    logging.debug(f"  actual:")
+    log_lines(indent, actual)
+
+    logging.debug(f"  wanted:")
+    log_lines(indent, wanted)
+
     assert_ne(wanted in actual, True)
 
 
@@ -247,21 +279,35 @@ def runcmd_stderr_doesnt_match_regex(ctx, regex=None):
 
 def _runcmd_output_matches_regex(actual, regex):
     assert_ne = globals()["assert_ne"]
+    log_lines = globals()["log_lines"]
+    indent = " " * 4
+
     r = re.compile(regex)
     m = r.search(actual)
+
     logging.debug("_runcmd_output_matches_regex:")
     logging.debug(f"  actual: {actual!r}")
+    log_lines(indent, actual)
+
     logging.debug(f"  regex: {regex!r}")
     logging.debug(f"  match: {m}")
+
     assert_ne(m, None)
 
 
 def _runcmd_output_doesnt_match_regex(actual, regex):
     assert_eq = globals()["assert_eq"]
+    log_lines = globals()["log_lines"]
+    indent = " " * 4
+
     r = re.compile(regex)
     m = r.search(actual)
+
     logging.debug("_runcmd_output_doesnt_match_regex:")
     logging.debug(f"  actual: {actual!r}")
+    log_lines(indent, actual)
+
     logging.debug(f"  regex: {regex!r}")
     logging.debug(f"  match: {m}")
+
     assert_eq(m, None)
diff --git a/share/python/template/context.py b/share/python/template/context.py
index 71ad320..0b9befb 100644
--- a/share/python/template/context.py
+++ b/share/python/template/context.py
@@ -1,4 +1,4 @@
-import logging
+# import logging
 import re
 
 
@@ -18,7 +18,7 @@ class Context:
         return self._vars[key]
 
     def __setitem__(self, key, value):
-        logging.debug("Context: key {!r} set to {!r}".format(key, value))
+        #        logging.debug("Context: key {!r} set to {!r}".format(key, value))
         self._vars[key] = value
 
     def keys(self):
diff --git a/share/python/template/main.py b/share/python/template/main.py
index 513db9e..fa42814 100644
--- a/share/python/template/main.py
+++ b/share/python/template/main.py
@@ -14,14 +14,47 @@ class MultilineFormatter(logging.Formatter):
         return lines.pop(0) + "\n".join("    %s" % line for line in lines)
 
 
-def log_dict(d, msg, level=0):
-    prefix = " " * level
-    if len(d) == 0:
-        logging.debug(f"{prefix}{msg}: empty")
+def indent(n):
+    return "  " * n
+
+
+def log_value(msg, level, v):
+    if is_multiline_string(v):
+        logging.debug(f"{indent(level)}{msg}:")
+        log_lines(indent(level + 1), v)
+    elif isinstance(v, dict) and v:
+        # Only non-empty dictionaries
+        logging.debug(f"{indent(level)}{msg}:")
+        for k in sorted(v.keys()):
+            log_value(f"{k!r}", level + 1, v[k])
+    elif isinstance(v, list) and v:
+        # Only non-empty lists
+        logging.debug(f"{indent(level)}{msg}:")
+        for i, x in enumerate(v):
+            log_value(f"{i}", level + 1, x)
     else:
-        logging.debug(f"{prefix}{msg}:")
-        for k in sorted(d.keys()):
-            logging.debug(f"{prefix}  {k}: {d[k]!r}")
+        logging.debug(f"{indent(level)}{msg}: {v!r}")
+
+
+def is_multiline_string(v):
+    if isinstance(v, str) and "\n" in v:
+        return True
+    elif isinstance(v, bytes) and b"\n" in v:
+        return True
+    else:
+        return False
+
+
+def log_lines(prefix, v):
+    if isinstance(v, str):
+        nl = "\n"
+    else:
+        nl = b"\n"
+    if nl in v:
+        for line in v.splitlines(keepends=True):
+            logging.debug(f"{prefix}{line!r}")
+    else:
+        logging.debug(f"{prefix}{v!r}")
 
 
 # Remember where we started from. The step functions may need to refer
diff --git a/share/python/template/scenarios.py b/share/python/template/scenarios.py
index 88d3370..96dcc69 100644
--- a/share/python/template/scenarios.py
+++ b/share/python/template/scenarios.py
@@ -81,7 +81,7 @@ class Scenario:
             step.cleanup(ctx)
 
     def _set_environment_variables_to(self, scendir, extra_env):
-        log_dict = globals()["log_dict"]
+        log_value = globals()["log_value"]
 
         minimal = {
             "PATH": "/bin:/usr/bin",
@@ -95,5 +95,5 @@ class Scenario:
         os.environ.update(extra_env)
         if not self._logged_env:
             self._logged_env = True
-            log_dict(dict(extra_env), "extra_env")
-            log_dict(dict(os.environ), "os.environ")
+            log_value("extra_env", 0, dict(extra_env))
+            log_value("os.environ", 0, dict(os.environ))