From 6fc61ab2019ef75c4d48283fac8d45db3fed89a4 Mon Sep 17 00:00:00 2001
From: "James E. Blair" <jim@acmegating.com>
Date: Mon, 1 Feb 2021 15:30:35 -0800
Subject: [PATCH] Format multi-line log entries

When tracebacks are sent to a log file or stderr using the default
configurations, it can be difficult to work with those logs.  Using
"grep" to search for messages or time periods will typically only
produce a single line of the error.

Further, on a busy system the error may be interleaved with other
log lines making extraction even harder.

To address both of these issues, add a formatter which formats every
line of a multi-line log message using the same format specifier.
This is quite readable when streaming or viewing a standard log file,
and it should cause all log lines to automatically appear in
ELK/splunk setups since they will all have the same message format.
(Though, those setups are probably better served with a native
logging configuration that sends the entire record together.)

It may be somewhat difficult if a multi-line log entry is recorded
on a busy system with multiple threads.  However, some judicious
grepping should help with that since all related lineswill have the
exact same timestamp (including microseconds).  Advanced users/devs
could specify a logging format with the thread id if necessary, though
I don't think we should do that by default.

Since this is implemented as a standard logging formatter, it can
be opted-out via logging config files.  This enables it by default,
which I think is reasonable for new users, but if we decide that we
would prefer opt-in, that is a simple change.

Sample output (from Zuul):

2021-01-29 10:59:02,004 DEBUG zuul.Scheduler: Run handler awake
2021-01-29 10:59:02,004 ERROR zuul.Scheduler: Exception in run handler:
2021-01-29 10:59:02,004 ERROR zuul.Scheduler:   Traceback (most recent call last):
2021-01-29 10:59:02,004 ERROR zuul.Scheduler:     File "/home/corvus/git/zuul/zuul/zuul/scheduler.py", line 1254, in run
2021-01-29 10:59:02,004 ERROR zuul.Scheduler:       raise Exception("Test")
2021-01-29 10:59:02,004 ERROR zuul.Scheduler:   Exception: Test
2021-01-29 10:59:02,005 DEBUG zuul.Scheduler: Run handler sleeping

Change-Id: I6d7e7e7a9e19d46a744f9ffac8d532fc6b4bba01
---
 nodepool/logconfig.py                         | 19 +++++++++++++++++++
 .../multiline-logging-b55f038e1077c7bb.yaml   |  5 +++++
 2 files changed, 24 insertions(+)
 create mode 100644 releasenotes/notes/multiline-logging-b55f038e1077c7bb.yaml

diff --git a/nodepool/logconfig.py b/nodepool/logconfig.py
index d8cbc0da8..3f296b1a1 100644
--- a/nodepool/logconfig.py
+++ b/nodepool/logconfig.py
@@ -25,6 +25,7 @@ _DEFAULT_SERVER_LOGGING_CONFIG = {
     'version': 1,
     'formatters': {
         'simple': {
+            'class': 'nodepool.logconfig.MultiLineFormatter',
             'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'
         },
     },
@@ -89,6 +90,24 @@ def load_config(filename: str):
     return FileLoggingConfig(filename)
 
 
+class MultiLineFormatter(logging.Formatter):
+    def format(self, record):
+        rec = super().format(record)
+        ret = []
+        # Save the existing message and re-use this record object to
+        # format each line.
+        saved_msg = record.message
+        for i, line in enumerate(rec.split('\n')):
+            if i:
+                record.message = '  ' + line
+                ret.append(self.formatMessage(record))
+            else:
+                ret.append(line)
+        # Restore the message
+        record.message = saved_msg
+        return '\n'.join(ret)
+
+
 class LoggingConfig(object, metaclass=abc.ABCMeta):
 
     @abc.abstractmethod
diff --git a/releasenotes/notes/multiline-logging-b55f038e1077c7bb.yaml b/releasenotes/notes/multiline-logging-b55f038e1077c7bb.yaml
new file mode 100644
index 000000000..75009d9ad
--- /dev/null
+++ b/releasenotes/notes/multiline-logging-b55f038e1077c7bb.yaml
@@ -0,0 +1,5 @@
+---
+features:
+  - |
+    Multi-line log messages (such as tracebacks from image builds) are now
+    prefixed in the same manner as single-line messages.