NAS-133329 / 25.04 / Fix python tracebacks for syslog messages

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))

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']