From 4c9112db9b0fe895e8f18f0cdb704c0c45a09806 Mon Sep 17 00:00:00 2001 From: nullishamy Date: Wed, 6 Sep 2023 19:28:59 +0100 Subject: [PATCH 1/6] 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. --- bot.py | 15 +++++++--- core/config.py | 1 + core/models.py | 77 ++++++++++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 87 insertions(+), 6 deletions(-) diff --git a/bot.py b/bot.py index b23b2449b2..4d1bf4dfee 100644 --- a/bot.py +++ b/bot.py @@ -43,6 +43,7 @@ InvalidConfigError, PermissionLevel, SafeFormatter, + configure_log_format, configure_logging, getLogger, ) @@ -69,6 +70,9 @@ def __init__(self): self.config = ConfigManager(self) self.config.populate_cache() + self.log_file_name = os.path.join(temp_dir, f"{self.token.split('.')[0]}.log") + self._configure_logging() + intents = discord.Intents.all() if not self.config["enable_presence_intent"]: intents.presences = False @@ -83,10 +87,6 @@ def __init__(self): self._started = False self.threads = ThreadManager(self) - - self.log_file_name = os.path.join(temp_dir, f"{self.token.split('.')[0]}.log") - self._configure_logging() - self.plugin_db = PluginDatabaseClient(self) # Deprecated self.startup() @@ -180,6 +180,12 @@ async def load_extensions(self): def _configure_logging(self): level_text = self.config["log_level"].upper() + format = self.config["log_format"].lower() + + # Initial call to configure the format, so that any errors + # that occur from now on will be formatted correctly + configure_log_format(format) + logging_levels = { "CRITICAL": logging.CRITICAL, "ERROR": logging.ERROR, @@ -198,6 +204,7 @@ def _configure_logging(self): logger.info("Logging level: %s", level_text) logger.info("Log file: %s", self.log_file_name) + logger.info("Log format: %s", format) configure_logging(self.log_file_name, log_level) logger.debug("Successfully configured logging.") diff --git a/core/config.py b/core/config.py index 9476352573..3fa3659711 100644 --- a/core/config.py +++ b/core/config.py @@ -178,6 +178,7 @@ class ConfigManager: "disable_updates": False, # Logging "log_level": "INFO", + "log_format": "basic", # data collection "data_collection": True, } diff --git a/core/models.py b/core/models.py index 2eab1ceebb..a089a0aaea 100644 --- a/core/models.py +++ b/core/models.py @@ -6,6 +6,7 @@ from enum import IntEnum from logging.handlers import RotatingFileHandler from string import Formatter +import json import discord from discord.ext import commands @@ -94,16 +95,80 @@ def line(self, level="info"): ) +class JsonFormatter(logging.Formatter): + """ + Formatter that outputs JSON strings after parsing the LogRecord. + + @param dict fmt_dict: Key: logging format attribute pairs. Defaults to {"message": "message"}. + @param str time_format: time.strftime() format string. Default: "%Y-%m-%dT%H:%M:%S" + @param str msec_format: Microsecond formatting. Appended at the end. Default: "%s.%03dZ" + """ + def __init__(self, fmt_dict: dict = None, time_format: str = "%Y-%m-%dT%H:%M:%S", msec_format: str = "%s.%03dZ"): + self.fmt_dict = fmt_dict if fmt_dict is not None else {"message": "message"} + self.default_time_format = time_format + self.default_msec_format = msec_format + self.datefmt = 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: + """ + 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) + logging.setLoggerClass(ModmailLogger) log_level = logging.INFO loggers = set() ch = logging.StreamHandler(stream=sys.stdout) ch.setLevel(log_level) -formatter = logging.Formatter( +basic_formatter = logging.Formatter( "%(asctime)s %(name)s[%(lineno)d] - %(levelname)s: %(message)s", datefmt="%m/%d/%y %H:%M:%S" ) -ch.setFormatter(formatter) +json_formatter = JsonFormatter({ + "level": "levelname", + "message": "message", + "loggerName": "name", + "processName": "processName", + "processID": "process", + "threadName": "threadName", + "threadID": "thread", + "timestamp": "asctime" +}) + +ch.setFormatter(basic_formatter) ch_debug = None @@ -126,6 +191,14 @@ def format(self, record): return super().format(record) +def configure_log_format(format): + global ch + + if format == 'json': + ch.setFormatter(json_formatter) + else: + ch.setFormatter(basic_formatter) + def configure_logging(name, level=None): global ch_debug, log_level ch_debug = RotatingFileHandler(name, mode="a+", maxBytes=48000, backupCount=1, encoding="utf-8") From 2d59947737bb7b3d3ff8bf0b02cdce75ffa3b164 Mon Sep 17 00:00:00 2001 From: nullishamy Date: Sat, 9 Sep 2023 14:08:43 +0100 Subject: [PATCH 2/6] Allow JSON to be selected when creating handlers --- core/models.py | 67 ++++++++++++++++++-------------------------------- 1 file changed, 24 insertions(+), 43 deletions(-) diff --git a/core/models.py b/core/models.py index a6dc20477e..f649bd59d8 100644 --- a/core/models.py +++ b/core/models.py @@ -135,15 +135,26 @@ def format(self, record): record.msg = self.ansi_escape.sub("", record.msg) return super().format(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, @@ -152,6 +163,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, @@ -178,6 +190,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, @@ -192,20 +207,24 @@ def create_log_handler( """ if filename is None and rotating: raise ValueError("`filename` must be set to instantiate a `RotatingFileHandler`.") - + 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 @@ -213,30 +232,9 @@ def create_log_handler( log_level = logging.INFO loggers = set() -ch = logging.StreamHandler(stream=sys.stdout) -ch.setLevel(log_level) -basic_formatter = logging.Formatter( - "%(asctime)s %(name)s[%(lineno)d] - %(levelname)s: %(message)s", datefmt="%m/%d/%y %H:%M:%S" -) - -json_formatter = JsonFormatter({ - "level": "levelname", - "message": "message", - "loggerName": "name", - "processName": "processName", - "processID": "process", - "threadName": "threadName", - "threadID": "thread", - "timestamp": "asctime" -}) - -ch.setFormatter(basic_formatter) - -ch_debug = None ch = create_log_handler(level=log_level) ch_debug: Optional[RotatingFileHandler] = None - def getLogger(name=None) -> ModmailLogger: logger = logging.getLogger(name) logger.setLevel(log_level) @@ -247,23 +245,6 @@ def getLogger(name=None) -> ModmailLogger: return logger -class FileFormatter(logging.Formatter): - ansi_escape = re.compile(r"\x1B\[[0-?]*[ -/]*[@-~]") - - def format(self, record): - record.msg = self.ansi_escape.sub("", record.msg) - return super().format(record) - - -def configure_log_format(format): - global ch - - if format == 'json': - ch.setFormatter(json_formatter) - else: - ch.setFormatter(basic_formatter) - -def configure_logging(name, level=None): def configure_logging(bot) -> None: global ch_debug, log_level From 09c814506b8fd70dbb209576ad0bbb843cce3e0d Mon Sep 17 00:00:00 2001 From: nullishamy Date: Sat, 9 Sep 2023 14:17:14 +0100 Subject: [PATCH 3/6] Allow different formats to be selected for streams/files --- core/config.py | 3 ++- core/models.py | 13 ++++++++++++- 2 files changed, 14 insertions(+), 2 deletions(-) diff --git a/core/config.py b/core/config.py index 512b50d3ff..a9e16a0df1 100644 --- a/core/config.py +++ b/core/config.py @@ -178,7 +178,8 @@ class ConfigManager: "disable_updates": False, # Logging "log_level": "INFO", - "log_format": "basic", + "stream_log_format": "plain", + "file_log_format": "plain", "discord_log_level": "INFO", # data collection "data_collection": True, diff --git a/core/models.py b/core/models.py index f649bd59d8..442c5b21ff 100644 --- a/core/models.py +++ b/core/models.py @@ -246,7 +246,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() @@ -271,8 +275,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) From ea75f53a88246e47282b2bdb74f3cf7d8984e9f5 Mon Sep 17 00:00:00 2001 From: Amy Date: Sat, 9 Sep 2023 18:32:56 +0100 Subject: [PATCH 4/6] Remove old / unused code --- bot.py | 3 --- 1 file changed, 3 deletions(-) diff --git a/bot.py b/bot.py index cc6de29e1c..45530a908f 100644 --- a/bot.py +++ b/bot.py @@ -43,7 +43,6 @@ InvalidConfigError, PermissionLevel, SafeFormatter, - configure_log_format, configure_logging, getLogger, ) @@ -69,8 +68,6 @@ def __init__(self): self.config = ConfigManager(self) self.config.populate_cache() - self.log_file_name = os.path.join(temp_dir, f"{self.token.split('.')[0]}.log") - intents = discord.Intents.all() if not self.config["enable_presence_intent"]: intents.presences = False From 92ea8fc9e2ac6beb402c10a849313a6ad40049ed Mon Sep 17 00:00:00 2001 From: Amy Date: Sat, 9 Sep 2023 18:36:30 +0100 Subject: [PATCH 5/6] Add new config opts to helpfile --- core/config_help.json | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/core/config_help.json b/core/config_help.json index f909d27821..501c265827 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.", From 859dc2316fe28d59344a0869b3013ba4dba9ca57 Mon Sep 17 00:00:00 2001 From: Jerrie-Aries Date: Sun, 10 Sep 2023 03:15:41 +0000 Subject: [PATCH 6/6] Formatting, basic typing and reorder for consistency in project. --- core/models.py | 82 ++++++++++++++++++++++++++++++-------------------- 1 file changed, 49 insertions(+), 33 deletions(-) diff --git a/core/models.py b/core/models.py index 442c5b21ff..2a397541c1 100644 --- a/core/models.py +++ b/core/models.py @@ -1,3 +1,4 @@ +import json import logging import os import re @@ -9,8 +10,7 @@ from logging import FileHandler, StreamHandler, Handler from logging.handlers import RotatingFileHandler from string import Formatter -import json -from typing import Optional +from typing import Dict, Optional import discord from discord.ext import commands @@ -79,15 +79,26 @@ class JsonFormatter(logging.Formatter): """ Formatter that outputs JSON strings after parsing the LogRecord. - @param dict fmt_dict: Key: logging format attribute pairs. Defaults to {"message": "message"}. - @param str time_format: time.strftime() format string. Default: "%Y-%m-%dT%H:%M:%S" - @param str msec_format: Microsecond formatting. Appended at the end. Default: "%s.%03dZ" + 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: dict = None, time_format: str = "%Y-%m-%dT%H:%M:%S", msec_format: str = "%s.%03dZ"): - self.fmt_dict = fmt_dict if fmt_dict is not None else {"message": "message"} - self.default_time_format = time_format - self.default_msec_format = msec_format - self.datefmt = None + + 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: """ @@ -95,10 +106,10 @@ def usesTime(self) -> bool: """ return "asctime" in self.fmt_dict.values() - def formatMessage(self, record) -> dict: + 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. + 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()} @@ -108,7 +119,7 @@ def format(self, record) -> str: instead of a string. """ record.message = record.getMessage() - + if self.usesTime(): record.asctime = self.formatTime(record, self.datefmt) @@ -128,6 +139,7 @@ def format(self, record) -> str: return json.dumps(message_dict, default=str) + class FileFormatter(logging.Formatter): ansi_escape = re.compile(r"\x1B\[[0-?]*[ -/]*[@-~]") @@ -135,6 +147,7 @@ def format(self, record): record.msg = self.ansi_escape.sub("", record.msg) return super().format(record) + log_stream_formatter = logging.Formatter( "%(asctime)s %(name)s[%(lineno)d] - %(levelname)s: %(message)s", datefmt="%m/%d/%y %H:%M:%S" ) @@ -144,16 +157,18 @@ def format(self, record): 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" -}) +json_formatter = JsonFormatter( + { + "level": "levelname", + "message": "message", + "loggerName": "name", + "processName": "processName", + "processID": "process", + "threadName": "threadName", + "threadID": "thread", + "timestamp": "asctime", + } +) def create_log_handler( @@ -163,7 +178,7 @@ def create_log_handler( level: int = logging.DEBUG, mode: str = "a+", encoding: str = "utf-8", - format: str = 'plain', + format: str = "plain", maxBytes: int = 28000000, backupCount: int = 1, **kwargs, @@ -207,7 +222,7 @@ def create_log_handler( """ if filename is None and rotating: raise ValueError("`filename` must be set to instantiate a `RotatingFileHandler`.") - + if filename is None: handler = StreamHandler(stream=sys.stdout, **kwargs) formatter = log_stream_formatter @@ -219,8 +234,8 @@ def create_log_handler( filename, mode=mode, encoding=encoding, maxBytes=maxBytes, backupCount=backupCount, **kwargs ) formatter = log_file_formatter - - if format == 'json': + + if format == "json": formatter = json_formatter handler.setLevel(level) @@ -235,6 +250,7 @@ def create_log_handler( ch = create_log_handler(level=log_level) ch_debug: Optional[RotatingFileHandler] = None + def getLogger(name=None) -> ModmailLogger: logger = logging.getLogger(name) logger.setLevel(log_level) @@ -248,8 +264,8 @@ def getLogger(name=None) -> ModmailLogger: def configure_logging(bot) -> None: 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': + 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__) @@ -276,13 +292,13 @@ 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': + 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) + 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)