James E. Blair 6fc61ab201 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/", 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
2021-03-05 13:34:19 -08:00

223 lines
6.5 KiB

# Copyright 2017 Red Hat, Inc.
# 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
# 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 abc
import copy
import logging.config
import json
import os
import yaml
'version': 1,
'formatters': {
'simple': {
'class': 'nodepool.logconfig.MultiLineFormatter',
'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'
'handlers': {
'console': {
# Used for printing to stdout
'class': 'logging.StreamHandler',
'stream': 'ext://sys.stdout',
'level': 'INFO',
'formatter': 'simple',
'null': {
'class': 'logging.NullHandler',
'loggers': {
'nodepool': {
'handlers': ['console'],
'level': 'INFO',
'requests': {
'handlers': ['console'],
'level': 'WARN',
'openstack': {
'handlers': ['console'],
'level': 'WARN',
'kazoo': {
'handlers': ['console'],
'level': 'WARN',
'root': {'handlers': ['null']},
'normal': {
# Used for writing normal log files
'class': 'logging.handlers.WatchedFileHandler',
# This will get set to something real by DictLoggingConfig.server
'filename': '/var/log/nodepool/{server}.log',
'level': 'INFO',
'formatter': 'simple',
def _read_config_file(filename: str):
if not os.path.exists(filename):
raise ValueError("Unable to read logging config file at %s" % filename)
if os.path.splitext(filename)[1] in ('.yml', '.yaml', '.json'):
return yaml.safe_load(open(filename, 'r'))
return filename
def load_config(filename: str):
config = _read_config_file(filename)
if isinstance(config, dict):
return DictLoggingConfig(config)
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
# Restore the message
record.message = saved_msg
return '\n'.join(ret)
class LoggingConfig(object, metaclass=abc.ABCMeta):
def apply(self):
"""Apply the config information to the current logging config."""
class DictLoggingConfig(LoggingConfig, metaclass=abc.ABCMeta):
def __init__(self, config):
self._config = config
def apply(self):
def writeJson(self, filename: str):
with open(filename, 'w') as f:
f.write(json.dumps(self._config, indent=2))
class ServerLoggingConfig(DictLoggingConfig):
def __init__(self, config=None, server=None):
if not config:
config = copy.deepcopy(_DEFAULT_SERVER_LOGGING_CONFIG)
super(ServerLoggingConfig, self).__init__(config=config)
if server:
self.server = server
def server(self):
return self._server
def server(self, server):
self._server = server
# Add the normal file handler. It's not included in the default
# config above because we're templating out the filename. Also, we
# only want to add the handler if we're actually going to use it.
for name, handler in _DEFAULT_SERVER_FILE_HANDLERS.items():
server_handler = copy.deepcopy(handler)
server_handler['filename'] = server_handler['filename'].format(
self._config['handlers'][name] = server_handler
# Change everything configured to write to stdout to write to
# log files instead.
for logger in self._config['loggers'].values():
if logger['handlers'] == ['console']:
logger['handlers'] = ['normal']
def setDebug(self):
# Change level from INFO to DEBUG
for section in ('handlers', 'loggers'):
for handler in self._config[section].values():
if handler.get('level') == 'INFO':
handler['level'] = 'DEBUG'
class FileLoggingConfig(LoggingConfig):
def __init__(self, filename):
self._filename = filename
def apply(self):
def get_annotated_logger(logger, event_id=None, node_request_id=None,
# Note: 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
extra = {}
if event_id is not None:
extra["event_id"] = event_id
if node_request_id is not None:
extra['node_request'] = node_request_id
if node_id is not None:
extra["node"] = node_id
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", {})
new_msg = []
event_id = extra.get("event_id")
if event_id is not None:
new_msg.append('[e: {}]'.format(event_id))
node_request = extra.get("node_request")
if node_request is not None:
new_msg.append("[node_request: {}]".format(node_request))
node = extra.get("node")
if node is not None:
new_msg.append("[node: {}]".format(node))
msg = " ".join(new_msg)
return msg, kwargs