Format multi-line log entries

There are two significant cases in Zuul where we may emit multi-line
log messages:

* Tracebacks
* Zuul config errors

When these 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:

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

2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: 1 errors detected during zuultest tenant configuration loading
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: Zuul encountered a syntax error while parsing its configuration in the
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:   repo local-project-config on branch master.  The error was:
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:     extra keys not allowed @ data['trigger']['github']
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:   The error appears in the following pipeline stanza:
...

Change-Id: I6d7e7e7a9e19d46a744f9ffac8d532fc6b4bba01
This commit is contained in:
James E. Blair
2021-01-26 13:05:20 -08:00
parent d12e582148
commit 16bb1bbf8c
2 changed files with 19 additions and 0 deletions

View File

@@ -73,6 +73,7 @@ _DEFAULT_SERVER_LOGGING_CONFIG = {
'version': 1,
'formatters': {
'simple': {
'class': 'zuul.lib.logutil.MultiLineFormatter',
'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'
},
},

View File

@@ -52,3 +52,21 @@ class EventIdLogAdapter(logging.LoggerAdapter):
new_msg.append(msg)
msg = ' '.join(new_msg)
return msg, kwargs
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)