From f63c22527167f79bc97972bebc7bf2a1fc3bc9b7 Mon Sep 17 00:00:00 2001 From: joamag Date: Wed, 8 Apr 2026 16:49:43 +0100 Subject: [PATCH 1/4] feat: add TRACE log level and patch_logging() Add TRACE log level (DEBUG - 5 = 5) for fine-grained protocol-level debugging, mirroring the implementation in Appier. Includes patch_logging() to register the level with Python's logging module, TRACE-aware format templates with file path and line number, and comprehensive test coverage. Co-Authored-By: Claude Opus 4.6 (1M context) --- CHANGELOG.md | 1 + src/quorum/__init__.py | 6 ++ src/quorum/base.py | 26 ++++- src/quorum/log.py | 45 ++++++++- src/quorum/test/log.py | 216 +++++++++++++++++++++++++++++++++++++++++ 5 files changed, 291 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 598a23b..9dfeab6 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/quorum/__init__.py b/src/quorum/__init__.py index 1cbeb5a..d942c65 100644 --- a/src/quorum/__init__.py +++ b/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, diff --git a/src/quorum/base.py b/src/quorum/base.py index 9292d6f..fd8c59c 100644 --- a/src/quorum/base.py +++ b/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) diff --git a/src/quorum/log.py b/src/quorum/log.py index a807e5b..08dafe1 100644 --- a/src/quorum/log.py +++ b/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,6 +85,12 @@ or an handler, this is used as an utility for debugging purposes more that a real feature for production systems """ +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 = ("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 @@ -96,6 +112,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,6 +344,18 @@ 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: @@ -333,7 +363,7 @@ def in_signature(callable, name): 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(): @@ -341,6 +371,14 @@ def has_exception(): 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 + logger.trace(message, *args, **kwargs) + + def debug(message, *args, **kwargs): kwargs.pop("log_trace", False) logger = common.base().get_log() @@ -399,3 +437,8 @@ def critical(message, *args, **kwargs): 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) diff --git a/src/quorum/test/log.py b/src/quorum/test/log.py index 1b6d7f9..83c8793 100644 --- a/src/quorum/test/log.py +++ b/src/quorum/test/log.py @@ -28,13 +28,229 @@ __license__ = "Apache License, Version 2.0" """ The license for the module """ +import os import logging +import tempfile +import unittest + +import logging.handlers import quorum +from quorum import log + class LogTest(quorum.TestCase): + @quorum.secured + def test_silent_value(self): + self.assertEqual(quorum.SILENT, logging.CRITICAL + 1) + self.assertEqual(type(quorum.SILENT), int) + + @quorum.secured + def test_silent_above_critical(self): + self.assertTrue(quorum.SILENT > logging.CRITICAL) + + @quorum.secured + def test_trace_value(self): + self.assertEqual(quorum.TRACE, 5) + self.assertEqual(quorum.TRACE, logging.DEBUG - 5) + self.assertEqual(type(quorum.TRACE), int) + + @quorum.secured + def test_trace_below_debug(self): + self.assertTrue(quorum.TRACE < logging.DEBUG) + + @quorum.secured + def test_level_ordering(self): + self.assertTrue(quorum.TRACE < logging.DEBUG) + self.assertTrue(logging.DEBUG < logging.INFO) + self.assertTrue(logging.INFO < logging.WARNING) + self.assertTrue(logging.WARNING < logging.ERROR) + self.assertTrue(logging.ERROR < logging.CRITICAL) + self.assertTrue(logging.CRITICAL < quorum.SILENT) + + @quorum.secured + def test_rotating_handler(self): + fd, path = tempfile.mkstemp() + os.close(fd) + try: + handler = quorum.rotating_handler(path=path, max_bytes=1024, max_log=3) + + self.assertEqual(type(handler), logging.handlers.RotatingFileHandler) + self.assertEqual(handler.maxBytes, 1024) + self.assertEqual(handler.backupCount, 3) + + handler.close() + finally: + os.unlink(path) + + @quorum.secured + def test_rotating_handler_defaults(self): + fd, path = tempfile.mkstemp() + os.close(fd) + try: + handler = quorum.rotating_handler(path=path) + + self.assertEqual(handler.maxBytes, 1048576) + self.assertEqual(handler.backupCount, 5) + + handler.close() + finally: + os.unlink(path) + + @quorum.secured + def test_patch_logging(self): + quorum.patch_logging() + + result = logging.getLevelName(quorum.TRACE) + + self.assertEqual(result, "TRACE") + + @quorum.secured + def test_patch_logging_reverse(self): + quorum.patch_logging() + + result = logging.getLevelName("TRACE") + + self.assertEqual(result, quorum.TRACE) + + @quorum.secured + def test_patch_logging_idempotent(self): + quorum.patch_logging() + quorum.patch_logging() + + result = logging.getLevelName(quorum.TRACE) + + self.assertEqual(result, "TRACE") + + @quorum.secured + def test_patch_logging_logger_trace(self): + quorum.patch_logging() + + logger = logging.getLogger("quorum.test.trace") + + self.assertTrue(hasattr(logger, "trace")) + self.assertTrue(callable(logger.trace)) + + @quorum.secured + def test_patch_logging_logger_trace_call(self): + quorum.patch_logging() + + logger = logging.getLogger("quorum.test.trace.call") + logger.setLevel(quorum.TRACE) + records = [] + handler = logging.Handler() + handler.setLevel(quorum.TRACE) + handler.emit = lambda record: records.append(record) + logger.addHandler(handler) + + try: + logger.trace("trace test message") + + self.assertEqual(len(records), 1) + self.assertEqual(records[0].getMessage(), "trace test message") + self.assertEqual(records[0].levelno, quorum.TRACE) + self.assertEqual(records[0].levelname, "TRACE") + finally: + logger.removeHandler(handler) + + @quorum.secured + def test_patch_logging_logger_trace_filtered(self): + quorum.patch_logging() + + logger = logging.getLogger("quorum.test.trace.filtered") + logger.setLevel(logging.DEBUG) + records = [] + handler = logging.Handler() + handler.setLevel(quorum.TRACE) + handler.emit = lambda record: records.append(record) + logger.addHandler(handler) + + try: + # the trace message should be filtered since the logger + # level is set to DEBUG which is above TRACE + logger.trace("this should be filtered") + + self.assertEqual(len(records), 0) + finally: + logger.removeHandler(handler) + + @quorum.secured + def test_level_trace_before_patch(self): + # temporarily removes the patched state to simulate a + # scenario where patch_logging() has not been called yet + patched = getattr(logging, "_quorum_patched", None) + if patched: + del logging._quorum_patched + trace_method = getattr(logging.Logger, "trace", None) + if trace_method: + del logging.Logger.trace + try: + result = quorum._level("TRACE") + + self.assertEqual(result, quorum.TRACE) + self.assertEqual(result, 5) + finally: + if patched: + logging._quorum_patched = patched + if trace_method: + logging.Logger.trace = trace_method + + @quorum.secured + def test_level_trace_after_patch(self): + quorum.patch_logging() + + result = quorum._level("TRACE") + + self.assertEqual(result, quorum.TRACE) + self.assertEqual(result, 5) + + @quorum.secured + def test_level_silent(self): + result = quorum._level("SILENT") + + self.assertEqual(result, quorum.SILENT) + + @quorum.secured + def test_level_integer(self): + result = quorum._level(logging.DEBUG) + + self.assertEqual(result, logging.DEBUG) + + @quorum.secured + def test_level_none(self): + result = quorum._level(None) + + self.assertEqual(result, None) + + @quorum.secured + def test_in_signature(self): + def sample(a, b, secure=None): + pass + + result = log.in_signature(sample, "secure") + + self.assertEqual(result, True) + + @quorum.secured + def test_in_signature_missing(self): + def sample(a, b): + pass + + result = log.in_signature(sample, "secure") + + self.assertEqual(result, False) + + @quorum.secured + def test_in_signature_args(self): + def sample(a, b, secure): + pass + + result = log.in_signature(sample, "secure") + + self.assertEqual(result, True) + @quorum.secured def test_memory_handler(self): memory_handler = quorum.MemoryHandler() From 9f9be744cd490935604be5c5994abddfbdefd875 Mon Sep 17 00:00:00 2001 From: joamag Date: Wed, 8 Apr 2026 17:01:56 +0100 Subject: [PATCH 2/4] chore: small structure fix --- src/quorum/test/log.py | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/src/quorum/test/log.py b/src/quorum/test/log.py index 83c8793..d83c75c 100644 --- a/src/quorum/test/log.py +++ b/src/quorum/test/log.py @@ -37,8 +37,6 @@ import quorum -from quorum import log - class LogTest(quorum.TestCase): @@ -229,7 +227,7 @@ def test_in_signature(self): def sample(a, b, secure=None): pass - result = log.in_signature(sample, "secure") + result = quorum.in_signature(sample, "secure") self.assertEqual(result, True) @@ -238,7 +236,7 @@ def test_in_signature_missing(self): def sample(a, b): pass - result = log.in_signature(sample, "secure") + result = quorum.in_signature(sample, "secure") self.assertEqual(result, False) @@ -247,7 +245,7 @@ def test_in_signature_args(self): def sample(a, b, secure): pass - result = log.in_signature(sample, "secure") + result = quorum.in_signature(sample, "secure") self.assertEqual(result, True) From 66122f3385607b7602932f6caef3e4c0e7a74554 Mon Sep 17 00:00:00 2001 From: joamag Date: Wed, 8 Apr 2026 17:07:46 +0100 Subject: [PATCH 3/4] feat: add stacklevel to logging wrapper functions Set stacklevel in trace(), debug(), info(), warning(), error(), and critical() wrapper functions so that %(pathname)s and %(lineno)d report the actual caller location instead of the wrapper code. Guarded by sys.version_info >= (3, 8) as stacklevel was introduced in Python 3.8. Co-Authored-By: Claude Opus 4.6 (1M context) --- src/quorum/log.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/quorum/log.py b/src/quorum/log.py index 08dafe1..df5bc4c 100644 --- a/src/quorum/log.py +++ b/src/quorum/log.py @@ -376,6 +376,8 @@ def trace(message, *args, **kwargs): logger = common.base().get_log() if not logger: return + if sys.version_info >= (3, 8): + kwargs.setdefault("stacklevel", 2) logger.trace(message, *args, **kwargs) @@ -384,6 +386,8 @@ def debug(message, *args, **kwargs): logger = common.base().get_log() if not logger: return + if sys.version_info >= (3, 8): + kwargs.setdefault("stacklevel", 2) logger.debug(message, *args, **kwargs) @@ -392,6 +396,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 @@ -405,6 +411,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 @@ -418,6 +426,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 @@ -431,6 +441,8 @@ 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 From dd0c7d7f2ea1be2c5469715a040fed47d3f391bc Mon Sep 17 00:00:00 2001 From: joamag Date: Wed, 8 Apr 2026 17:13:41 +0100 Subject: [PATCH 4/4] fix: add TRACE to LEVELS tuple and LEVEL_ALIAS map Include TRACE in the severity-ordered LEVELS tuple so that MemoryHandler.get_messages_l() properly stores and filters TRACE records. Add "TRAC" alias to LEVEL_ALIAS for consistent short-name resolution. Co-Authored-By: Claude Opus 4.6 (1M context) --- src/quorum/log.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/quorum/log.py b/src/quorum/log.py index df5bc4c..d1fbbae 100644 --- a/src/quorum/log.py +++ b/src/quorum/log.py @@ -91,12 +91,13 @@ used for fine-grained debugging of low-level operations like raw byte transfers and frame parsing """ -LEVELS = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") +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",