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.

(cherry picked from commit 23e6b49cc57cb41a0260686366e7ba86cac0ec4a)

diff --git a/bin/tests/system/isctest/log/basic.py b/bin/tests/system/isctest/log/basic.py
index 81991d4318218aa0b3b225c673d5266c033a381a..38ffab9bfc431418cafcd8da555fd2c6857810b7 100644 (file)
--- a/bin/tests/system/isctest/log/basic.py
+++ b/bin/tests/system/isctest/log/basic.py
@@ -11,11 +11,13 @@
 
 import logging
 from pathlib import Path
+import textwrap
 from typing import Dict, Optional
 
 
 CONFTEST_LOGGER = logging.getLogger("conftest")
 LOG_FORMAT = "%(asctime)s %(levelname)7s:%(name)s  %(message)s"
+LOG_INDENT = 4
 
 LOGGERS = {
     "conftest": None,
@@ -82,6 +84,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"]
@@ -90,6 +99,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 d87606296430c2603c747795fde24a48087d4a47..6e694a7efc710bc1a317990c73e046a6c7c7a6f9 100644 (file)
--- a/bin/tests/system/isctest/run.py
+++ b/bin/tests/system/isctest/run.py
@@ -33,17 +33,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:
@@ -64,7 +64,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