chore: clean up log files from generated Python programs

This is a step in the right direction, but may not be enough. We'll
see.

Multi-line log messages are no multiple lines in in the log file. All
but the first one are indented.

Dictionaries are listed with one key per line. argv as one item per line.

Various log messages that are just noise removed.

4 files changed, 39 insertions, 15 deletions

diff --git a/share/python/lib/runcmd.py b/share/python/lib/runcmd.py
index cc4fd38..c4d297c 100644
--- a/share/python/lib/runcmd.py
+++ b/share/python/lib/runcmd.py
@@ -48,6 +48,8 @@ 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"]
+
     ns = ctx.declare("_runcmd")
 
     # The Subplot Python template empties os.environ at startup, modulo a small
@@ -64,8 +66,8 @@ def runcmd_run(ctx, argv, **kwargs):
         env["PATH"] = pp + ":" + env["PATH"]
 
     logging.debug(f"runcmd_run")
-    logging.debug(f"  argv: {argv}")
-    logging.debug(f"  env: {env}")
+    log_dict(dict(enumerate(argv)), "argv", level=1)
+    log_dict(env, "env:", level=1)
     p = subprocess.Popen(
         argv, stdout=subprocess.PIPE, stderr=subprocess.PIPE, env=env, **kwargs
     )
@@ -76,8 +78,8 @@ def runcmd_run(ctx, argv, **kwargs):
     ns["stdout"] = stdout.decode("utf-8")
     ns["stderr"] = stderr.decode("utf-8")
     ns["exit"] = p.returncode
-    logging.debug(f"  ctx: {ctx}")
-    logging.debug(f"  ns: {ns}")
+    log_dict(ctx.as_dict(), "ctx", level=1)
+    log_dict(ns.as_dict(), "ns", level=1)
 
 
 # Step: prepend srcdir to PATH whenever runcmd runs a command.
diff --git a/share/python/template/context.py b/share/python/template/context.py
index d61316e..71ad320 100644
--- a/share/python/template/context.py
+++ b/share/python/template/context.py
@@ -21,6 +21,9 @@ class Context:
         logging.debug("Context: key {!r} set to {!r}".format(key, value))
         self._vars[key] = value
 
+    def keys(self):
+        return self._vars.keys()
+
     def __contains__(self, key):
         return key in self._vars
 
@@ -33,7 +36,6 @@ class Context:
     def declare(self, name):
         if name not in self._ns:
             self._ns[name] = NameSpace(name)
-            logging.debug(f"Context: declared {name}")
         return self._ns[name]
 
     def remember_value(self, name, value):
@@ -85,6 +87,9 @@ class NameSpace:
     def __getitem__(self, key):
         return self._dict[key]
 
+    def keys(self):
+        return self._dict.keys()
+
     def __contains__(self, key):
         return key in self._dict
 
diff --git a/share/python/template/main.py b/share/python/template/main.py
index 87e2782..3d98024 100644
--- a/share/python/template/main.py
+++ b/share/python/template/main.py
@@ -7,6 +7,23 @@ import tarfile
 import tempfile
 
 
+class MultilineFormatter(logging.Formatter):
+    def format(self, record):
+        s = super().format(record)
+        lines = list(s.splitlines())
+        return lines.pop(0) + "\n".join("    %w" % line for line in lines)
+
+
+def log_dict(d, msg, level=0):
+    prefix = " " * level
+    if len(d) == 0:
+        logging.debug(f"{prefix}{msg}: empty")
+    else:
+        logging.debug(f"{prefix}{msg}:")
+        for k in sorted(d.keys()):
+            logging.debug(f"{prefix}  {k}: {d[k]!r}")
+
+
 # Remember where we started from. The step functions may need to refer
 # to files there.
 srcdir = os.getcwd()
@@ -33,7 +50,7 @@ def setup_logging(args):
     if args.log:
         fmt = "%(asctime)s %(levelname)s %(message)s"
         datefmt = "%Y-%m-%d %H:%M:%S"
-        formatter = logging.Formatter(fmt, datefmt)
+        formatter = MultilineFormatter(fmt, datefmt)
 
         filename = os.path.abspath(os.path.join(srcdir, args.log))
         handler = logging.FileHandler(filename)
@@ -77,8 +94,6 @@ def main(scenarios):
     for env in args.env:
         (name, value) = env.split("=", 1)
         extra_env[name] = value
-    logging.debug(f"args.env: {args.env}")
-    logging.debug(f"env vars from command line; {extra_env}")
 
     try:
         for scen in todo:
diff --git a/share/python/template/scenarios.py b/share/python/template/scenarios.py
index 1e0ebf5..88d3370 100644
--- a/share/python/template/scenarios.py
+++ b/share/python/template/scenarios.py
@@ -32,16 +32,14 @@ class Step:
 
     def do(self, ctx):
         print("  step: {} {}".format(self._kind, self._text))
-        logging.info("  step: {} {}".format(self._kind, self._text))
+        logging.info("step: {} {}".format(self._kind, self._text))
         self._function(ctx, **self._args)
 
     def cleanup(self, ctx):
         if self._cleanup:
             print("  cleanup: {} {}".format(self._kind, self._text))
-            logging.info("  cleanup: {} {}".format(self._kind, self._text))
+            logging.info("cleanup: {} {}".format(self._kind, self._text))
             self._cleanup(ctx, **self._args)
-        else:
-            logging.info("  no cleanup defined: {} {}".format(self._kind, self._text))
 
 
 class Scenario:
@@ -49,6 +47,7 @@ class Scenario:
         self._title = None
         self._steps = []
         self._ctx = ctx
+        self._logged_env = False
 
     def get_title(self):
         return self._title
@@ -62,7 +61,6 @@ class Scenario:
     def run(self, datadir, extra_env):
         print("scenario: {}".format(self._title))
         logging.info("Scenario: {}".format(self._title))
-        logging.info("extra environment variables: {}".format(extra_env))
 
         scendir = tempfile.mkdtemp(dir=datadir)
         os.chdir(scendir)
@@ -83,6 +81,8 @@ class Scenario:
             step.cleanup(ctx)
 
     def _set_environment_variables_to(self, scendir, extra_env):
+        log_dict = globals()["log_dict"]
+
         minimal = {
             "PATH": "/bin:/usr/bin",
             "SHELL": "/bin/sh",
@@ -93,5 +93,7 @@ class Scenario:
         os.environ.clear()
         os.environ.update(minimal)
         os.environ.update(extra_env)
-        logging.debug(f"extra_env: {dict(extra_env)!r}")
-        logging.debug(f"os.environ: {dict(os.environ)!r}")
+        if not self._logged_env:
+            self._logged_env = True
+            log_dict(dict(extra_env), "extra_env")
+            log_dict(dict(os.environ), "os.environ")