James E. Blair
16bb1bbf8c
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
73 lines
2.3 KiB
Python
73 lines
2.3 KiB
Python
# Copyright 2019 BMW Group
|
|
#
|
|
# Licensed under the Apache License, Version 2.0 (the "License"); you may
|
|
# not use this file except in compliance with the License. You may obtain
|
|
# a copy of the License at
|
|
#
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
#
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
|
|
# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
|
|
# License for the specific language governing permissions and limitations
|
|
# under the License.
|
|
|
|
import logging
|
|
|
|
|
|
def get_annotated_logger(logger, event, build=None):
|
|
# Note(tobiash): When running with python 3.5 log adapters cannot be
|
|
# stacked. We need to detect this case and modify the original one.
|
|
if isinstance(logger, EventIdLogAdapter):
|
|
extra = logger.extra
|
|
else:
|
|
extra = {}
|
|
|
|
if event is not None:
|
|
if hasattr(event, 'zuul_event_id'):
|
|
extra['event_id'] = event.zuul_event_id
|
|
else:
|
|
extra['event_id'] = event
|
|
|
|
if build is not None:
|
|
extra['build'] = build
|
|
|
|
if isinstance(logger, EventIdLogAdapter):
|
|
return logger
|
|
|
|
return EventIdLogAdapter(logger, extra)
|
|
|
|
|
|
class EventIdLogAdapter(logging.LoggerAdapter):
|
|
def process(self, msg, kwargs):
|
|
msg, kwargs = super().process(msg, kwargs)
|
|
extra = kwargs.get('extra', {})
|
|
event_id = extra.get('event_id')
|
|
build = extra.get('build')
|
|
new_msg = []
|
|
if event_id is not None:
|
|
new_msg.append('[e: %s]' % event_id)
|
|
if build is not None:
|
|
new_msg.append('[build: %s]' % build)
|
|
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)
|