feat: add TRACE log level and patch_logging() (#20)

* feat: add TRACE log level and patch_logging()

Port TRACE log level support from appier (hivesolutions/appier#84) to colony.
Adds TRACE constant (logging.DEBUG - 5 = 5) and SILENT constant
(logging.CRITICAL + 1 = 51) for fine-grained protocol-level debugging.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

* feat: add trace() method and *args/**kwargs to PluginManager log methods

Adds trace() convenience method to PluginManager and makes all log
methods (debug, info, warning, error, critical) accept *args and
**kwargs for lazy evaluation support.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

* feat: add TRACE-aware logging format with pathname and lineno

When the log level is set to TRACE, automatically switches to a more
detailed format that includes file path and line number for fine-grained
debugging of low-level operations.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

* chore: new module starting

* fix: handle GLOBAL_CONFIG override for TRACE logging format

The GLOBAL_CONFIG always has a hardcoded logging_format value, so the
.get() default never triggers. Added explicit check to switch to the
trace format when the config value matches the default and the level
is TRACE.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

* chore: new logging format for trace

* chore: new black format

* chore: new logging format for trace

Passes stacklevel=2 in all PluginManager log methods (trace, debug,
info, warning, error, critical) so that pathname and lineno in the
format string reflect the actual caller, not the internal log method.
Guards stacklevel for Python < 3.8 where it is not supported, and
makes DEFAULT_LOGGING_FORMAT_TRACE conditional on Python 3.8+.

Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

* fix: trace reference

* fix: small spelling error in logging_util.py docstring

---------

Co-authored-by: Claude Opus 4.6 (1M context) <noreply@anthropic.com>

Author: joamag

CHANGELOG.md

@@ -9,7 +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
 
 ### Changed
 

src/colony/__main__.py

@@ -0,0 +1,30 @@
+#!/usr/bin/python
+# -*- coding: utf-8 -*-
+
+# Hive Colony Framework
+# Copyright (c) 2008-2024 Hive Solutions Lda.
+#
+# This file is part of Hive Colony Framework
+#
+# Hive Colony Framework is free software: you can redistribute it and/or modify
+# it under the terms of the Apache License as published by the Apache
+# Foundation, either version 2.0 of the License, or (at your option) any
+# later version.
+#
+# Hive Colony Framework is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# Apache License for more details.
+#
+# You should have received a copy of the Apache License along with
+# Hive Colony Framework If not, see <http://www.apache.org/licenses/>.
+
+__copyright__ = "Copyright (c) 2008-2024 Hive Solutions Lda."
+""" The copyright for the module """
+
+__license__ = "Apache License, Version 2.0"
+""" The license for the module """
+
+from colony_start import main
+
+main()

src/colony/base/__init__.py

@@ -89,7 +89,14 @@
     DATE_TIME_FORMAT,
     INFORMATION_PATH,
 )
-from .loggers import BroadcastHandler, MemoryHandler, LogstashHandler
+from .loggers import (
+    SILENT,
+    TRACE,
+    BroadcastHandler,
+    MemoryHandler,
+    LogstashHandler,
+    patch_logging,
+)
 from .system import (
     System,
     Plugin,

src/colony/base/loggers.py

@@ -64,6 +64,17 @@
 """ The maximum amount of time in between flush
 operations in the logstash handler """
 
+SILENT = logging.CRITICAL + 1
+""" The silent level used to silent all the logging
+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
@@ -386,3 +397,20 @@ def _build_api(self):
             return None
 
         return logstash.API()
+
+
+def patch_logging():
+    if hasattr(logging, "_colony_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._colony_patched = True
+
+
+def _trace(self, message, *args, **kwargs):
+    if self.isEnabledFor(TRACE):
+        self._log(TRACE, message, args, **kwargs)

src/colony/base/system.py

@@ -80,6 +80,15 @@
 DEFAULT_LOGGING_FORMAT = "%(asctime)s [%(levelname)s] %(message)s"
 """ The default logging format """
 
+DEFAULT_LOGGING_FORMAT_TRACE = (
+    "%(asctime)s [%(levelname)s] %(pathname)s:%(lineno)d | %(message)s"
+    if sys.version_info >= (3, 8)
+    else "%(asctime)s [%(levelname)s] %(message)s"
+)
+""" The format to be used when the logging level is set to TRACE,
+includes file path and line number on Python 3.8+ where stacklevel
+is supported for accurate caller information """
+
 DEFAULT_LOGGING_FILE_NAME_PREFIX = "colony"
 """ The default logging file name prefix """
 
@@ -236,6 +245,11 @@ def get_manager(self):
             raise exceptions.PluginSystemException("no plugin available")
         return self.plugin.manager
 
+    def trace(self, *args, **kwargs):
+        if self.plugin == None:
+            raise exceptions.PluginSystemException("no plugin available")
+        return self.plugin.trace(*args, **kwargs)
+
     def debug(self, *args, **kwargs):
         if self.plugin == None:
             raise exceptions.PluginSystemException("no plugin available")
@@ -1380,6 +1394,19 @@ def log_stack_trace(self, level=logging.DEBUG):
             formatted_traceback_line_stripped = formatted_traceback_line.rstrip()
             self.logger.log(level, formatted_traceback_line_stripped)
 
+    def trace(self, message, *args, **kwargs):
+        """
+        Adds the given trace message to the logger.
+
+        :type message: String
+        :param message: The trace message to be added to the logger.
+        """
+
+        # formats the logger message then prints the
+        # trace message to the current stream
+        logger_message = self.format_logger_message(message)
+        self.logger.trace(logger_message, *args, **kwargs)
+
     def debug(self, message, *args, **kwargs):
         """
         Adds the given debug message to the logger.
@@ -2223,6 +2250,11 @@ def start_logger(self, log_level=DEFAULT_LOGGING_LEVEL):
         :param log_level: The log level of the logger.
         """
 
+        # 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
+        loggers.patch_logging()
+
         # retrieves the minimal log level between the current
         # log level and the default one (as specified)
         minimal_log_level = (
@@ -2312,8 +2344,16 @@ def start_logger(self, log_level=DEFAULT_LOGGING_LEVEL):
         logstash_handler.setLevel(minimal_log_level)
 
         # retrieves the logging format and uses it
-        # to create the proper logging formatter
-        logging_format = GLOBAL_CONFIG.get("logging_format", DEFAULT_LOGGING_FORMAT)
+        # to create the proper logging formatter, in case the
+        # log level is set to trace uses the trace format that
+        # includes the file path and line number for debugging
+        is_trace = log_level <= loggers.TRACE
+        default_format = (
+            DEFAULT_LOGGING_FORMAT_TRACE if is_trace else DEFAULT_LOGGING_FORMAT
+        )
+        logging_format = GLOBAL_CONFIG.get("logging_format", default_format)
+        if logging_format == DEFAULT_LOGGING_FORMAT and is_trace:
+            logging_format = DEFAULT_LOGGING_FORMAT_TRACE
         formatter = logging.Formatter(logging_format)
 
         # sets the formatter in the stream and rotating
@@ -6004,7 +6044,27 @@ def log_stack_trace(self, level=logging.DEBUG):
             # prints a log message with the formatted traceback line
             self.logger.log(level, formatted_traceback_line_stripped)
 
-    def debug(self, message):
+    def trace(self, message, *args, **kwargs):
+        """
+        Adds the given trace message to the logger.
+
+        :type message: String
+        :param message: The trace message to be added to the logger.
+        """
+
+        # in case no logger is defined it's not possible
+        # to print the message as a trace
+        if not self.logger:
+            return
+
+        # formats the logger message and prints it
+        # as a trace message into the logger
+        logger_message = self.format_logger_message(message)
+        if sys.version_info >= (3, 8):
+            kwargs.setdefault("stacklevel", 2)
+        self.logger.log(loggers.TRACE, logger_message, *args, **kwargs)
+
+    def debug(self, message, *args, **kwargs):
         """
         Adds the given debug message to the logger.
 
@@ -6020,9 +6080,11 @@ def debug(self, message):
         # formats the logger message and prints it
         # as a debug message into the logger
         logger_message = self.format_logger_message(message)
-        self.logger.debug(logger_message)
+        if sys.version_info >= (3, 8):
+            kwargs.setdefault("stacklevel", 2)
+        self.logger.debug(logger_message, *args, **kwargs)
 
-    def info(self, message):
+    def info(self, message, *args, **kwargs):
         """
         Adds the given info message to the logger.
 
@@ -6038,9 +6100,11 @@ def info(self, message):
         # formats the logger message and prints it
         # as an info message into the logger
         logger_message = self.format_logger_message(message)
-        self.logger.info(logger_message)
+        if sys.version_info >= (3, 8):
+            kwargs.setdefault("stacklevel", 2)
+        self.logger.info(logger_message, *args, **kwargs)
 
-    def warning(self, message):
+    def warning(self, message, *args, **kwargs):
         """
         Adds the given warning message to the logger.
 
@@ -6056,12 +6120,14 @@ def warning(self, message):
         # formats the logger message and prints it
         # as a warning message into the logger
         logger_message = self.format_logger_message(message)
-        self.logger.warning(logger_message)
+        if sys.version_info >= (3, 8):
+            kwargs.setdefault("stacklevel", 2)
+        self.logger.warning(logger_message, *args, **kwargs)
 
         # logs the stack trace
         self.log_stack_trace(level=logging.INFO)
 
-    def error(self, message):
+    def error(self, message, *args, **kwargs):
         """
         Adds the given error message to the logger.
 
@@ -6077,12 +6143,14 @@ def error(self, message):
         # formats the logger message and prints it
         # as an error message into the logger
         logger_message = self.format_logger_message(message)
-        self.logger.error(logger_message)
+        if sys.version_info >= (3, 8):
+            kwargs.setdefault("stacklevel", 2)
+        self.logger.error(logger_message, *args, **kwargs)
 
         # logs the stack trace
         self.log_stack_trace(level=logging.WARNING)
 
-    def critical(self, message):
+    def critical(self, message, *args, **kwargs):
         """
         Adds the given critical message to the logger.
 
@@ -6094,7 +6162,9 @@ def critical(self, message):
         logger_message = self.format_logger_message(message)
 
         # prints the critical message
-        self.logger.critical(logger_message)
+        if sys.version_info >= (3, 8):
+            kwargs.setdefault("stacklevel", 2)
+        self.logger.critical(logger_message, *args, **kwargs)
 
         # logs the stack trace
         self.log_stack_trace(level=logging.ERROR)
@@ -6570,6 +6640,23 @@ def get_uptime(self):
         # about the uptime for the current plugin system
         return uptime
 
+    def is_trace(self):
+        """
+        Checks if the current logging level is set to trace,
+        this check may be used to action conditional code
+        execution for fine-grained debugging purposes.
+
+        :rtype: bool
+        :return: Value indicating if the current logging level
+        is set to trace (for fine-grained debugging).
+        """
+
+        if not self.logger:
+            return False
+        if not self.logger.level:
+            return False
+        return self.logger.level <= loggers.TRACE
+
     def is_development(self):
         """
         Checks if the current run mode in execution is of type

src/colony/base/system.pyi

@@ -46,6 +46,7 @@ class System:
 
     def __init__(self, plugin) -> None: ...
     def get_manager(self): ...
+    def trace(self, *args, **kwargs): ...
     def debug(self, *args, **kwargs): ...
     def info(self, *args, **kwargs): ...
     def warning(self, *args, **kwargs): ...
@@ -138,11 +139,12 @@ class Plugin:
     def get_author_name(self): ...
     def get_uptime(self): ...
     def log_stack_trace(self, level=...) -> None: ...
-    def debug(self, message) -> None: ...
-    def info(self, message) -> None: ...
-    def warning(self, message) -> None: ...
-    def error(self, message) -> None: ...
-    def critical(self, message) -> None: ...
+    def trace(self, message, *args, **kwargs) -> None: ...
+    def debug(self, message, *args, **kwargs) -> None: ...
+    def info(self, message, *args, **kwargs) -> None: ...
+    def warning(self, message, *args, **kwargs) -> None: ...
+    def error(self, message, *args, **kwargs) -> None: ...
+    def critical(self, message, *args, **kwargs) -> None: ...
     def format_logger_message(self, message): ...
     def _get_capabilities_allowed_names(self): ...
 
@@ -388,11 +390,12 @@ class PluginManager:
     def generate_system_information_map(self) -> None: ...
     def get_log_handler(self, name): ...
     def log_stack_trace(self, level=...) -> None: ...
-    def debug(self, message) -> None: ...
-    def info(self, message) -> None: ...
-    def warning(self, message) -> None: ...
-    def error(self, message) -> None: ...
-    def critical(self, message) -> None: ...
+    def trace(self, message, *args, **kwargs) -> None: ...
+    def debug(self, message, *args, **kwargs) -> None: ...
+    def info(self, message, *args, **kwargs) -> None: ...
+    def warning(self, message, *args, **kwargs) -> None: ...
+    def error(self, message, *args, **kwargs) -> None: ...
+    def critical(self, message, *args, **kwargs) -> None: ...
     def format_logger_message(self, message): ...
     def print_all_plugins(self) -> None: ...
     def get_prefix_paths(self): ...
@@ -428,6 +431,7 @@ class PluginManager:
     def get_environment(self): ...
     def get_system_information_map(self): ...
     def get_uptime(self): ...
+    def is_trace(self): ...
     def is_development(self): ...
     def is_production(self): ...
     def echo(self, value: str = "echo"): ...

src/colony/libs/__init__.py

@@ -111,6 +111,8 @@
 from .lazy_util import LazyClass, LazyIteratorClass, is_lazy, Lazy, LazyIterator
 from .list_util import list_intersect, list_extend, list_no_duplicates
 from .logging_util import (
+    SILENT,
+    TRACE,
     getLogger,
     getLevelName,
     getLevelInt,