Add JSON logging support (modmail-dev#3305)

* Add JSON logging support

This adds support for JSON logging, along with the relevant options required.

This does not change the default log behaviour, so should be backwards compatible.

It is opt in via the LOG_FORMAT option, which can be 'json' to use the new logger, or anything else to fallback
to the old behaviour.

This is implemented in terms of a custom formatter, which is optionally applied to the stdout stream.
The debug stream is unaffected by this.

* Allow JSON to be selected when creating handlers

* Allow different formats to be selected for streams/files

* Remove old / unused code

* Add new config opts to helpfile

* Formatting, basic typing and reorder for consistency in project.

---------

Co-authored-by: Jerrie-Aries <hidzrie@gmail.com>
Co-authored-by: Taku <45324516+Taaku18@users.noreply.github.com>

Author: 3 people

core/config.py

@@ -178,6 +178,8 @@ class ConfigManager:
         "disable_updates": False,
         # Logging
         "log_level": "INFO",
+        "stream_log_format": "plain",
+        "file_log_format": "plain",
         "discord_log_level": "INFO",
         # data collection
         "data_collection": True,

core/config_help.json

@@ -1129,6 +1129,24 @@
       "This configuration can only to be set through `.env` file or environment (config) variables."
     ]
   },
+  "stream_log_format": {
+    "default": "plain",
+    "description": "The logging format when through a stream, can be 'plain' or 'json'",
+    "examples": [
+    ],
+    "notes": [
+      "This configuration can only to be set through `.env` file or environment (config) variables."
+    ]
+  },
+  "file_log_format": {
+    "default": "plain",
+    "description": "The logging format when logging to a file, can be 'plain' or 'json'",
+    "examples": [
+    ],
+    "notes": [
+      "This configuration can only to be set through `.env` file or environment (config) variables."
+    ]
+  },
   "discord_log_level": {
     "default": "INFO",
     "description": "The `discord.py` library logging level for logging to stdout.",

core/models.py

@@ -1,3 +1,4 @@
+import json
 import logging
 import os
 import re
@@ -9,7 +10,7 @@
 from logging import FileHandler, StreamHandler, Handler
 from logging.handlers import RotatingFileHandler
 from string import Formatter
-from typing import Optional
+from typing import Dict, Optional
 
 import discord
 from discord.ext import commands
@@ -74,6 +75,71 @@ def line(self, level="info"):
             )
 
 
+class JsonFormatter(logging.Formatter):
+    """
+    Formatter that outputs JSON strings after parsing the LogRecord.
+
+    Parameters
+    ----------
+    fmt_dict : Optional[Dict[str, str]]
+        {key: logging format attribute} pairs. Defaults to {"message": "message"}.
+    time_format: str
+        time.strftime() format string. Default: "%Y-%m-%dT%H:%M:%S"
+    msec_format: str
+        Microsecond formatting. Appended at the end. Default: "%s.%03dZ"
+    """
+
+    def __init__(
+        self,
+        fmt_dict: Optional[Dict[str, str]] = None,
+        time_format: str = "%Y-%m-%dT%H:%M:%S",
+        msec_format: str = "%s.%03dZ",
+    ):
+        self.fmt_dict: Dict[str, str] = fmt_dict if fmt_dict is not None else {"message": "message"}
+        self.default_time_format: str = time_format
+        self.default_msec_format: str = msec_format
+        self.datefmt: Optional[str] = None
+
+    def usesTime(self) -> bool:
+        """
+        Overwritten to look for the attribute in the format dict values instead of the fmt string.
+        """
+        return "asctime" in self.fmt_dict.values()
+
+    def formatMessage(self, record) -> Dict[str, str]:
+        """
+        Overwritten to return a dictionary of the relevant LogRecord attributes instead of a string.
+        KeyError is raised if an unknown attribute is provided in the fmt_dict.
+        """
+        return {fmt_key: record.__dict__[fmt_val] for fmt_key, fmt_val in self.fmt_dict.items()}
+
+    def format(self, record) -> str:
+        """
+        Mostly the same as the parent's class method, the difference being that a dict is manipulated and dumped as JSON
+        instead of a string.
+        """
+        record.message = record.getMessage()
+
+        if self.usesTime():
+            record.asctime = self.formatTime(record, self.datefmt)
+
+        message_dict = self.formatMessage(record)
+
+        if record.exc_info:
+            # Cache the traceback text to avoid converting it multiple times
+            # (it's constant anyway)
+            if not record.exc_text:
+                record.exc_text = self.formatException(record.exc_info)
+
+        if record.exc_text:
+            message_dict["exc_info"] = record.exc_text
+
+        if record.stack_info:
+            message_dict["stack_info"] = self.formatStack(record.stack_info)
+
+        return json.dumps(message_dict, default=str)
+
+
 class FileFormatter(logging.Formatter):
     ansi_escape = re.compile(r"\x1B\[[0-?]*[ -/]*[@-~]")
 
@@ -85,11 +151,25 @@ def format(self, record):
 log_stream_formatter = logging.Formatter(
     "%(asctime)s %(name)s[%(lineno)d] - %(levelname)s: %(message)s", datefmt="%m/%d/%y %H:%M:%S"
 )
+
 log_file_formatter = FileFormatter(
     "%(asctime)s %(name)s[%(lineno)d] - %(levelname)s: %(message)s",
     datefmt="%Y-%m-%d %H:%M:%S",
 )
 
+json_formatter = JsonFormatter(
+    {
+        "level": "levelname",
+        "message": "message",
+        "loggerName": "name",
+        "processName": "processName",
+        "processID": "process",
+        "threadName": "threadName",
+        "threadID": "thread",
+        "timestamp": "asctime",
+    }
+)
+
 
 def create_log_handler(
     filename: Optional[str] = None,
@@ -98,6 +178,7 @@ def create_log_handler(
     level: int = logging.DEBUG,
     mode: str = "a+",
     encoding: str = "utf-8",
+    format: str = "plain",
     maxBytes: int = 28000000,
     backupCount: int = 1,
     **kwargs,
@@ -124,6 +205,9 @@ def create_log_handler(
     encoding : str
         If this keyword argument is specified along with filename, its value is used when the `FileHandler` is created,
         and thus used when opening the output file. Defaults to 'utf-8'.
+    format : str
+        The format to output with, can either be 'json' or 'plain'. Will apply to whichever handler is created,
+        based on other conditional logic.
     maxBytes : int
         The max file size before the rollover occurs. Defaults to 28000000 (28MB). Rollover occurs whenever the current
         log file is nearly `maxBytes` in length; but if either of `maxBytes` or `backupCount` is zero,
@@ -141,23 +225,28 @@ def create_log_handler(
 
     if filename is None:
         handler = StreamHandler(stream=sys.stdout, **kwargs)
-        handler.setFormatter(log_stream_formatter)
+        formatter = log_stream_formatter
     elif not rotating:
         handler = FileHandler(filename, mode=mode, encoding=encoding, **kwargs)
-        handler.setFormatter(log_file_formatter)
+        formatter = log_file_formatter
     else:
         handler = RotatingFileHandler(
             filename, mode=mode, encoding=encoding, maxBytes=maxBytes, backupCount=backupCount, **kwargs
         )
-        handler.setFormatter(log_file_formatter)
+        formatter = log_file_formatter
+
+    if format == "json":
+        formatter = json_formatter
 
     handler.setLevel(level)
+    handler.setFormatter(formatter)
     return handler
 
 
 logging.setLoggerClass(ModmailLogger)
 log_level = logging.INFO
 loggers = set()
+
 ch = create_log_handler(level=log_level)
 ch_debug: Optional[RotatingFileHandler] = None
 
@@ -173,7 +262,11 @@ def getLogger(name=None) -> ModmailLogger:
 
 
 def configure_logging(bot) -> None:
-    global ch_debug, log_level
+    global ch_debug, log_level, ch
+
+    stream_log_format, file_log_format = bot.config["stream_log_format"], bot.config["file_log_format"]
+    if stream_log_format == "json":
+        ch.setFormatter(json_formatter)
 
     logger = getLogger(__name__)
     level_text = bot.config["log_level"].upper()
@@ -198,8 +291,15 @@ def configure_logging(bot) -> None:
 
     logger.info("Log file: %s", bot.log_file_path)
     ch_debug = create_log_handler(bot.log_file_path, rotating=True)
+
+    if file_log_format == "json":
+        ch_debug.setFormatter(json_formatter)
+
     ch.setLevel(log_level)
 
+    logger.info("Stream log format: %s", stream_log_format)
+    logger.info("File log format: %s", file_log_format)
+
     for log in loggers:
         log.setLevel(log_level)
         log.addHandler(ch_debug)