feat: add TRACE log level and patch_logging()

CHANGELOG.md

@@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Added
 
+* TRACE log level and `patch_logging()` for fine-grained protocol-level debugging
 * Support for `conf_override()` context manager to temporarily override configuration values
 * Docstring documentation for `xlsx_to_map` function
 * Unit tests for `xlsx_raw` function in formats module

src/quorum/__init__.py

@@ -108,6 +108,7 @@
     get_handler,
     get_bundle,
     is_devel,
+    is_trace,
     finalize,
     before_request,
     after_request,
@@ -123,6 +124,7 @@
     has_context,
     ensure_context,
     onrun,
+    _level,
 )
 from .config import (
     conf,
@@ -215,13 +217,17 @@
 )
 from .jsonf import load_json
 from .log import (
+    SILENT,
+    TRACE,
     MemoryHandler,
     BaseFormatter,
     ThreadFormatter,
     rotating_handler,
     smtp_handler,
+    patch_logging,
     in_signature,
     has_exception,
+    trace,
     debug,
     info,
     warning,

src/quorum/base.py

@@ -680,9 +680,22 @@ def start_log(
     app,
     name=None,
     level=logging.WARN,
-    format_base=log.LOGGING_FORMAT,
-    format_tid=log.LOGGING_FORMAT_TID,
+    format_base=None,
+    format_tid=None,
 ):
+    # patches the logging infra-structure so that the TRACE level
+    # is properly registered and available for usage, this call
+    # is idempotent and safe to be called multiple times
+    log.patch_logging()
+
+    is_trace = level <= log.TRACE
+    format_base = format_base or (
+        log.LOGGING_FORMAT_TRACE if is_trace else log.LOGGING_FORMAT
+    )
+    format_tid = format_tid or (
+        log.LOGGING_FORMAT_TRACE_TID if is_trace else log.LOGGING_FORMAT_TID
+    )
+
     # tries to retrieve some of the default configuration values
     # that are going to be used in the logger startup
     format = config.conf("LOGGING_FORMAT", None)
@@ -918,6 +931,13 @@ def is_devel(app=None):
     return level < logging.INFO
 
 
+def is_trace(app=None):
+    level = get_level(app=app)
+    if not level:
+        return False
+    return level <= log.TRACE
+
+
 def finalize(value):
     # returns an empty string as value representation
     # for unset values, this is the default representation
@@ -1127,6 +1147,8 @@ def _level(level):
         return level
     if level == "SILENT":
         return log.SILENT
+    if level == "TRACE":
+        return log.TRACE
     if hasattr(logging, "_checkLevel"):
         return logging._checkLevel(level)
     return logging.getLevelName(level)

src/quorum/log.py

@@ -55,6 +55,16 @@
 includes the thread identification number and should be
 used for messages called from outside the main thread """
 
+LOGGING_FORMAT_TRACE_T = "%%(asctime)s [%%(name)s] [%%(levelname)s] %s%%(pathname)s:%%(lineno)d | %%(message)s"
+""" The format to be used when the logging level is set to TRACE,
+includes file path and line number to allow for fine-grained debugging
+of low-level protocol operations """
+
+LOGGING_FORMAT_TRACE_TID_T = "%%(asctime)s [%%(name)s] [%%(levelname)s] %s[%%(thread)d] %%(pathname)s:%%(lineno)d | %%(message)s"
+""" The format to be used when the logging level is set to TRACE and
+the thread is not the main one, includes file path, line number and
+thread identification number """
+
 LOGGING_EXTRA = "[%(name)s] " if config.conf("LOGGING_EXTRA", cast=bool) else ""
 """ The extra logging attributes that are going to be applied
 to the format strings to obtain the final on the logging """
@@ -75,12 +85,19 @@
 or an handler, this is used as an utility for debugging
 purposes more that a real feature for production systems """
 
-LEVELS = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL")
+TRACE = logging.DEBUG - 5
+""" The trace level used for extremely detailed and verbose
+logging of protocol-level operations, this is meant to be
+used for fine-grained debugging of low-level operations
+like raw byte transfers and frame parsing """
+
+LEVELS = ("TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL")
 """ The sequence of levels from the least sever to the
 most sever this sequence may be used to find all the
 levels that are considered more sever that a level """
 
 LEVEL_ALIAS = {
+    "TRAC": "TRACE",
     "DEBU": "DEBUG",
     "WARN": "WARNING",
     "INF": "INFO",
@@ -96,6 +113,8 @@
 
 LOGGING_FORMAT = LOGGING_FORMAT_T % LOGGING_EXTRA
 LOGGING_FORMAT_TID = LOGGING_FORMAT_TID_T % LOGGING_EXTRA
+LOGGING_FORMAT_TRACE = LOGGING_FORMAT_TRACE_T % LOGGING_EXTRA
+LOGGING_FORMAT_TRACE_TID = LOGGING_FORMAT_TRACE_TID_T % LOGGING_EXTRA
 
 
 class MemoryHandler(logging.Handler):
@@ -326,26 +345,50 @@ def smtp_handler(
     )
 
 
+def patch_logging():
+    if hasattr(logging, "_quorum_patched"):
+        return
+
+    # patches the logging infra-structure adding the trace level
+    # support and the corresponding trace method to the logger
+    logging.addLevelName(TRACE, "TRACE")
+    logging.Logger.trace = _trace
+
+    logging._quorum_patched = True
+
+
 def in_signature(callable, name):
     has_full = hasattr(inspect, "getfullargspec")
     if has_full:
         spec = inspect.getfullargspec(callable)
     else:
         spec = inspect.getargspec(callable)
     args, _varargs, kwargs = spec[:3]
-    return (args and name in args) or (kwargs and "secure" in kwargs)
+    return bool((args and name in args) or (kwargs and "secure" in kwargs))
 
 
 def has_exception():
     info = sys.exc_info()
     return not info == (None, None, None)
 
 
+def trace(message, *args, **kwargs):
+    kwargs.pop("log_trace", False)
+    logger = common.base().get_log()
+    if not logger:
+        return
+    if sys.version_info >= (3, 8):
+        kwargs.setdefault("stacklevel", 2)
+    logger.trace(message, *args, **kwargs)
+
+
 def debug(message, *args, **kwargs):
     kwargs.pop("log_trace", False)
     logger = common.base().get_log()
     if not logger:
         return
+    if sys.version_info >= (3, 8):
+        kwargs.setdefault("stacklevel", 2)
     logger.debug(message, *args, **kwargs)
 
 
@@ -354,6 +397,8 @@ def info(message, *args, **kwargs):
     logger = common.base().get_log()
     if not logger:
         return
+    if sys.version_info >= (3, 8):
+        kwargs.setdefault("stacklevel", 2)
     logger.info(message, *args, **kwargs)
     if not log_trace or not has_exception():
         return
@@ -367,6 +412,8 @@ def warning(message, *args, **kwargs):
     logger = common.base().get_log()
     if not logger:
         return
+    if sys.version_info >= (3, 8):
+        kwargs.setdefault("stacklevel", 2)
     logger.warning(message, *args, **kwargs)
     if not log_trace or not has_exception():
         return
@@ -380,6 +427,8 @@ def error(message, *args, **kwargs):
     logger = common.base().get_log()
     if not logger:
         return
+    if sys.version_info >= (3, 8):
+        kwargs.setdefault("stacklevel", 2)
     logger.error(message, *args, **kwargs)
     if not log_trace or not has_exception():
         return
@@ -393,9 +442,16 @@ def critical(message, *args, **kwargs):
     logger = common.base().get_log()
     if not logger:
         return
+    if sys.version_info >= (3, 8):
+        kwargs.setdefault("stacklevel", 2)
     logger.critical(message, *args, **kwargs)
     if not log_trace or not has_exception():
         return
     lines = traceback.format_exc().splitlines()
     for line in lines:
         logger.error(line, *args, **kwargs)
+
+
+def _trace(self, message, *args, **kwargs):
+    if self.isEnabledFor(TRACE):
+        self._log(TRACE, message, args, **kwargs)