diff --git a/src/middlewared/middlewared/logger.py b/src/middlewared/middlewared/logger.py index 77a5755a367a6..4ba5469a214ca 100644 --- a/src/middlewared/middlewared/logger.py +++ b/src/middlewared/middlewared/logger.py @@ -6,6 +6,7 @@ import warnings from .logging.console_formatter import ConsoleLogFormatter from collections import deque +from json import dumps from dataclasses import dataclass # markdown debug is also considered useless @@ -120,6 +121,47 @@ def get_ident(self): # written to files in /var/log and so they are not members of ALL_LOG_FILES MIDDLEWARE_TNAUDIT = TNLog('TNAUDIT_MIDDLEWARE', '', '', None) +BASIC_SYSLOG_TRANSLATION = str.maketrans({'\n': '\\n'}) + + +class TNLogFormatter(logging.Formatter): + """ logging formatter to convert python exception into structured data """ + + def _escape_rfc_generic(self, msg: str) -> str: + return msg.translate(BASIC_SYSLOG_TRANSLATION) + + def format(self, record: logging.LogRecord) -> str: + exc_info = record.exc_info + exc_text = record.exc_text + stack_info = record.stack_info + structured_data = {} + + record.exc_info = None + record.exc_text = None + record.stack_info = None + + # Generate message following formatter rules + # Then collapse to single line for sending to syslog. + msg = self._escape_rfc_generic(super().format(record)) + if exc_info: + structured_data['exception'] = self.formatException(exc_info) + + if stack_info: + structured_data['stack'] = self.formatStack(stack_info) + + if structured_data: + structured_data['type'] = 'PYTHON_EXCEPTION' + json_data = dumps({'TNLOG': structured_data}) + msg += f' @cee:{json_data}' + + record.exc_info = exc_info + record.exc_text = exc_text + record.stack_info = stack_info + return msg + + +QFORMATTER = TNLogFormatter() + class TNSyslogHandler(logging.handlers.SysLogHandler): def __init__( @@ -240,6 +282,10 @@ def setup_syslog_handler(tnlog: TNLog, fallback: logging.Handler | None) -> logg log_queue = queue.Queue() queue_handler = logging.handlers.QueueHandler(log_queue) + # We need to handle python exceptions (format into structured data) + # rather than allowing the QueueHandler to perform exception formatting, + queue_handler.setFormatter(QFORMATTER) + # Set up syslog handler with deque to store failed messages until # they can be flushed. This can happen if syslog-ng isn't ready yet. syslog_handler = TNSyslogHandler(pending_queue=deque(maxlen=tnlog.pending_maxlen)) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 185fbd7ec8af5..266c1593b674a 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -1,3 +1,4 @@ +import json import logging import logging.handlers import os @@ -12,6 +13,7 @@ DEFAULT_LOGFORMAT, DEFAULT_SYSLOG_PATH, LOGFILE, + QFORMATTER, setup_syslog_handler, TNSyslogHandler, ) @@ -90,6 +92,7 @@ def working_syslog(current_test_name): can successfully write to the middleware log file. """ handler = TNSyslogHandler(address=DEFAULT_SYSLOG_PATH, pending_queue=deque()) + handler.setFormatter(QFORMATTER) handler.ident = DEFAULT_IDENT logger = logging.getLogger(current_test_name) logger.addHandler(handler) @@ -177,3 +180,31 @@ def test__middleware_logger_paths(tnlog, test_message): with open(tnlog.logfile, 'r') as f: contents = f.read() assert test_message in contents + + +def test__syslog_exception_parameterization(working_syslog, test_message): + logger, handler = working_syslog + assert handler.pending_queue is not None + assert handler.fallback_handler is None + + log_line = None + + try: + os.stat('/var/empty/nonexistent') + except Exception: + logger.critical(test_message, exc_info=True) + + sleep(SYSLOG_WRITE_WAIT) + with open(LOGFILE, 'r') as f: + for line in f: + if line.startswith(test_message): + log_line = line + break + + assert log_line is not None + assert '@cee' in log_line + + exc = log_line.split('@cee:')[1] + data = json.loads(exc) + assert data['TNLOG']['type'] == 'PYTHON_EXCEPTION' + assert 'FileNotFoundError' in data['TNLOG']['exception']