From bcbf9b45c564032fac60adbf6fd0382e98f9ca60 Mon Sep 17 00:00:00 2001 From: Amy Date: Sun, 19 Nov 2023 05:45:13 +0000 Subject: [PATCH] Add JSON logging support (#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 Co-authored-by: Taku <45324516+Taaku18@users.noreply.github.com> --- core/config.py | 2 + core/config_help.json | 18 +++++++ core/models.py | 110 ++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 125 insertions(+), 5 deletions(-) diff --git a/core/config.py b/core/config.py index 527b2dc19f9..a9e16a0df16 100644 --- a/core/config.py +++ b/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, diff --git a/core/config_help.json b/core/config_help.json index f909d278211..501c2658276 100644 --- a/core/config_help.json +++ b/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.", diff --git a/core/models.py b/core/models.py index 29f6af71bb1..2a397541c1d 100644 --- a/core/models.py +++ b/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)