From bf2f0605ccf9162f19e23274eff3d6f082dd342a Mon Sep 17 00:00:00 2001 From: Scott Gasch Date: Wed, 1 Mar 2023 22:16:17 -0800 Subject: [PATCH] Do this logging stuff the right way. --- src/pyutils/logging_utils.py | 129 +++++++++++++++++++---------------- 1 file changed, 71 insertions(+), 58 deletions(-) diff --git a/src/pyutils/logging_utils.py b/src/pyutils/logging_utils.py index 86d11ab..1e37190 100644 --- a/src/pyutils/logging_utils.py +++ b/src/pyutils/logging_utils.py @@ -48,7 +48,6 @@ import io import logging import os import sys -import threading from logging.config import fileConfig from logging.handlers import RotatingFileHandler, SysLogHandler from typing import Any, Callable, Dict, Iterable, List, Optional @@ -470,65 +469,90 @@ class OnlyInfoFilter(logging.Filter): return record.levelno == logging.INFO -def _get_current_pidtid() -> str: - return f"{os.getpid()}/{threading.get_ident()}" +def prepend_all_logger_messages( + prefix: str, logger: logging.Logger +) -> logging.LoggerAdapter: + """Helper method around the creation of a LogAdapter that prepends + a given string to every log message produced. + Args: + prefix: the message to prepend to every log message. + logger: the logger whose messages to modify. -LOGGING_PREFIXES_BY_PIDTID = {} + Returns: + A new logger wrapping the old one with the given behavior. + The old logger will continue to behave as usual; simply drop + the reference to this wrapper when it's no longer needed. + """ + return PrependingLogAdapter.wrap_logger(prefix, logger) -def register_thread_logging_prefix(message: Optional[str]) -> None: - """A function that allows a thread to register a string that - should be prepended to every log message it produces from now on. - Relies on the :class:`MillisecondAwareOptionallyAugmentingFormatter` - being used with the logging Handler which is the default if you're - using this module. +class PrependingLogAdapter(logging.LoggerAdapter): + def process(self, msg, kwargs): + return f'{self.extra.get("prefix", "")}{msg}', kwargs - Args: - message: the message to prepend to all logging done by the - current thread. If None or "", clears any previous - message registered. - """ - pidtid = _get_current_pidtid() - if message and len(message) > 0: - LOGGING_PREFIXES_BY_PIDTID[pidtid] = message - elif pidtid in LOGGING_PREFIXES_BY_PIDTID: - del LOGGING_PREFIXES_BY_PIDTID[pidtid] + @staticmethod + def wrap_logger(prefix: str, logger: logging.Logger) -> logging.LoggerAdapter: + """Helper method around the creation of a LogAdapter that prepends + a given string to every log message produced. + Args: + prefix: the message to prepend to every log message. + logger: the logger whose messages to modify. -LOGGING_SUFFIXES_BY_PIDTID = {} + Returns: + A new logger wrapping the old one with the given behavior. + The old logger will continue to behave as usual; simply drop + the reference to this wrapper when it's no longer needed. + """ + assert prefix + return PrependingLogAdapter(logger, {"prefix": prefix}) -def register_thread_logging_suffix(message: Optional[str]) -> None: - """A function that allows a thread to register a string that - should be appended to every log message it produces from now on. - Relies on the :class:`MillisecondAwareOptionallyAugmentingFormatter` - being used with the logging Handler which is the default if you're - using this module. +def append_all_logger_messages( + suffix: str, logger: logging.Logger +) -> logging.LoggerAdapter: + """Helper method around the creation of a LogAdapter that appends + a given string to every log message produced. Args: - message: the message to append to all logging done by the - current thread. If None or "", clears any previous - message registered. + suffix: the message to prepend to every log message. + logger: the logger whose messages to modify. + + Returns: + A new logger wrapping the old one with the given behavior. + The old logger will continue to behave as usual; simply drop + the reference to this wrapper when it's no longer needed. """ - pidtid = _get_current_pidtid() - if message and len(message) > 0: - LOGGING_SUFFIXES_BY_PIDTID[pidtid] = message - elif pidtid in LOGGING_PREFIXES_BY_PIDTID: - del LOGGING_SUFFIXES_BY_PIDTID[pidtid] + return AppendingLogAdapter.wrap_logger(suffix, logger) -class MillisecondAwareOptionallyAugmentingFormatter(logging.Formatter): +class AppendingLogAdapter(logging.LoggerAdapter): + def process(self, msg, kwargs): + return f'{msg}{self.extra.get("suffix", "")}', kwargs + + @staticmethod + def wrap_logger(suffix: str, logger: logging.Logger) -> logging.LoggerAdapter: + """Helper method around the creation of a LogAdapter that appends + a given string to every log message produced. + + Args: + suffix: the message to prepend to every log message. + logger: the logger whose messages to modify. + + Returns: + A new logger wrapping the old one with the given behavior. + The old logger will continue to behave as usual; simply drop + the reference to this wrapper when it's no longer needed. + """ + assert suffix + return AppendingLogAdapter(logger, {"suffix": suffix}) + + +class MillisecondAwareFormatter(logging.Formatter): """A formatter for adding milliseconds to log messages which, for whatever reason, the default Python logger doesn't do. - This formatter also consults a map of pid+tid -> message from this - module allowing threads to optionally and automatically prepend a - message to all logging data they output. If the pid+tid is not - found nothing is prepended. See - :meth:`register_thread_logging_prefix` and - :meth:`register_thread_logging_suffix` for details. - .. note:: You probably don't need to use this directly but it is @@ -540,20 +564,9 @@ class MillisecondAwareOptionallyAugmentingFormatter(logging.Formatter): converter = datetime.datetime.fromtimestamp # type: ignore - @overrides - def format(self, record): - pidtid = _get_current_pidtid() - prefix = LOGGING_PREFIXES_BY_PIDTID.get(pidtid, None) - if prefix: - record.msg = prefix + record.msg - suffix = LOGGING_SUFFIXES_BY_PIDTID.get(pidtid, None) - if suffix: - record.msg = record.msg + suffix - return super().format(record) - @overrides def formatTime(self, record, datefmt=None): - ct = MillisecondAwareOptionallyAugmentingFormatter.converter( + ct = MillisecondAwareFormatter.converter( record.created, pytz.timezone("US/Pacific") ) if datefmt: @@ -720,7 +733,7 @@ def initialize_logging(logger=None) -> logging.Logger: assert facility is not None handler = SysLogHandler(facility=facility, address="/dev/log") handler.setFormatter( - MillisecondAwareOptionallyAugmentingFormatter( + MillisecondAwareFormatter( fmt=fmt, datefmt=config.config["logging_date_format"], ) @@ -741,7 +754,7 @@ def initialize_logging(logger=None) -> logging.Logger: backupCount=backup_count, ) handler.setFormatter( - MillisecondAwareOptionallyAugmentingFormatter( + MillisecondAwareFormatter( fmt=fmt, datefmt=config.config["logging_date_format"], ) @@ -752,7 +765,7 @@ def initialize_logging(logger=None) -> logging.Logger: if config.config["logging_console"]: handler = logging.StreamHandler(sys.stderr) handler.setFormatter( - MillisecondAwareOptionallyAugmentingFormatter( + MillisecondAwareFormatter( fmt=fmt, datefmt=config.config["logging_date_format"], ) -- 2.47.1