Indent multiline output in pytest logging

When multiline message is logged, indent all but the first line (which
will be preceeded by the LOG_FORMAT). This improves the clarity of logs,
as it's immediately clear which lines are regular log output, and which
ones are multiline debug output.

Adjust the isctest.run.cmd() stdout/stderr logging to this new format.

diff --git a/bin/tests/system/isctest/log/basic.py b/bin/tests/system/isctest/log/basic.py
index 67121d2e24b4947a4a9d6c3bdd08041adabeccd8..3474f1b4433ea852c1728ca576163836397c3100 100644 (file)
--- a/bin/tests/system/isctest/log/basic.py
+++ b/bin/tests/system/isctest/log/basic.py
@@ -11,10 +11,12 @@
 
 import logging
 from pathlib import Path
+import textwrap
 from typing import Dict, Optional
 
 
 LOG_FORMAT = "%(asctime)s %(levelname)7s:%(name)s  %(message)s"
+LOG_INDENT = 4
 
 LOGGERS = {
     "conftest": None,
@@ -77,6 +79,13 @@ def deinit_test_logger():
     LOGGERS["test"] = None
 
 
+def indent_message(msg):
+    lines = msg.splitlines()
+    first = lines[0] + "\n"
+    to_indent = "\n".join(lines[1:])
+    return first + textwrap.indent(to_indent, " " * LOG_INDENT)
+
+
 def log(lvl: int, msg: str, *args, **kwargs):
     """Log message with the most-specific logger currently available."""
     logger = LOGGERS["test"]
@@ -85,6 +94,8 @@ def log(lvl: int, msg: str, *args, **kwargs):
     if logger is None:
         logger = LOGGERS["conftest"]
     assert logger is not None
+    if "\n" in msg:
+        msg = indent_message(msg)
     logger.log(lvl, msg, *args, **kwargs)
 
 

diff --git a/bin/tests/system/isctest/run.py b/bin/tests/system/isctest/run.py
index 5c994ce3778928c4997fca719f1422cea0db8c94..4c3acc5d2b666f5ac2846a283dbf6fa2ddd4970a 100644 (file)
--- a/bin/tests/system/isctest/run.py
+++ b/bin/tests/system/isctest/run.py
@@ -31,17 +31,17 @@ def cmd(
     env: Optional[dict] = None,
 ):
     """Execute a command with given args as subprocess."""
-    isctest.log.debug(f"command: {' '.join(args)}")
+    isctest.log.debug(f"isctest.run.cmd(): {' '.join(args)}")
 
     def print_debug_logs(procdata):
         if procdata:
             if log_stdout and procdata.stdout:
                 isctest.log.debug(
-                    f"~~~ cmd stdout ~~~\n{procdata.stdout.decode('utf-8')}\n~~~~~~~~~~~~~~~~~~"
+                    f"isctest.run.cmd(): (stdout)\n{procdata.stdout.decode('utf-8')}"
                 )
             if log_stderr and procdata.stderr:
                 isctest.log.debug(
-                    f"~~~ cmd stderr ~~~\n{procdata.stderr.decode('utf-8')}\n~~~~~~~~~~~~~~~~~~"
+                    f"isctest.run.cmd(): (stderr)\n{procdata.stderr.decode('utf-8')}"
                 )
 
     if env is None:
@@ -62,7 +62,7 @@ def cmd(
         return proc
     except subprocess.CalledProcessError as exc:
         print_debug_logs(exc)
-        isctest.log.debug(f"  return code: {exc.returncode}")
+        isctest.log.debug(f"isctest.run.cmd(): (return code) {exc.returncode}")
         if raise_on_exception:
             raise exc
         return exc