diff --git a/CHANGELOG.md b/CHANGELOG.md index 3127953d..8773a6d7 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/colony/__main__.py b/src/colony/__main__.py new file mode 100644 index 00000000..c0d7bd35 --- /dev/null +++ b/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 . + +__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() diff --git a/src/colony/base/__init__.py b/src/colony/base/__init__.py index a3308a86..21c912bf 100644 --- a/src/colony/base/__init__.py +++ b/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, diff --git a/src/colony/base/loggers.py b/src/colony/base/loggers.py index 7ad2a94d..d4be9db4 100644 --- a/src/colony/base/loggers.py +++ b/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) diff --git a/src/colony/base/system.py b/src/colony/base/system.py index 9fb44836..50ea73fc 100644 --- a/src/colony/base/system.py +++ b/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 diff --git a/src/colony/base/system.pyi b/src/colony/base/system.pyi index f774b75a..c7dbe915 100644 --- a/src/colony/base/system.pyi +++ b/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"): ... diff --git a/src/colony/libs/__init__.py b/src/colony/libs/__init__.py index 85dc4720..81e83ff8 100644 --- a/src/colony/libs/__init__.py +++ b/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, diff --git a/src/colony/libs/logging_util.py b/src/colony/libs/logging_util.py index 35a63b11..6ac61e6d 100644 --- a/src/colony/libs/logging_util.py +++ b/src/colony/libs/logging_util.py @@ -28,6 +28,11 @@ __license__ = "Apache License, Version 2.0" """ The license for the module """ +SILENT = 51 +""" 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 """ + CRITICAL = 50 """ Critical logging level """ @@ -43,6 +48,12 @@ DEBUG = 10 """ Debug logging level """ +TRACE = 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 """ + NOTSET = 0 """ Not set logging level """ @@ -50,33 +61,39 @@ """ Alias to WARNING log level """ _levelNames = { + SILENT: "SILENT", CRITICAL: "CRITICAL", ERROR: "ERROR", WARNING: "WARNING", INFO: "INFO", DEBUG: "DEBUG", + TRACE: "TRACE", NOTSET: "NOTSET", + "SILENT": SILENT, "CRITICAL": CRITICAL, "ERROR": ERROR, "WARN": WARNING, "WARNING": WARNING, "INFO": INFO, "DEBUG": DEBUG, + "TRACE": TRACE, "NOTSET": NOTSET, } """ The map relating the log levels with the textual representation and vice-versa """ _levelValues = { + "SILENT": SILENT, "CRITICAL": CRITICAL, "ERROR": ERROR, "WARN": WARNING, "WARNING": WARNING, "INFO": INFO, "DEBUG": DEBUG, + "TRACE": TRACE, "NOTSET": NOTSET, } -""" Map tha associated the textual representation of the +""" Map that associates the textual representation of the log level with the integer value """ @@ -148,6 +165,16 @@ def setLevel(self, level): pass + def trace(self, msg, *args, **kwargs): + """ + Prints a trace message to the logger. + + :type msg: String + :param msg: The message to print. + """ + + pass + def debug(self, msg, *args, **kwargs): """ Prints a debug message to the logger. diff --git a/src/colony/libs/logging_util.pyi b/src/colony/libs/logging_util.pyi index 08318001..1b2de778 100644 --- a/src/colony/libs/logging_util.pyi +++ b/src/colony/libs/logging_util.pyi @@ -1,11 +1,13 @@ from logging import Handler, Logger, Formatter as BaseFormatter from typing import Mapping +SILENT: int CRITICAL: int ERROR: int WARNING: int INFO: int DEBUG: int +TRACE: int NOTSET: int WARN = ... _levelNames: Mapping[str | int, str | int] @@ -18,6 +20,7 @@ def getLevelInt(levelName: str) -> int: ... class DummyLogger: def __init__(self, name: str, level: int = ...): ... def setLevel(self, level: int): ... + def trace(self, msg: str, *args, **kwargs): ... def debug(self, msg: str, *args, **kwargs): ... def info(self, msg: str, *args, **kwargs): ... def warning(self, msg: str, *args, **kwargs): ... diff --git a/src/colony/test/base/loggers.py b/src/colony/test/base/loggers.py index d8969d33..f6400137 100644 --- a/src/colony/test/base/loggers.py +++ b/src/colony/test/base/loggers.py @@ -32,6 +32,8 @@ import colony +from colony.base import loggers + try: import unittest.mock as mock except ImportError: @@ -44,6 +46,131 @@ class LoggersTest(colony.ColonyTestCase): methods and functions of colony. """ + def test_silent_value(self): + self.assertEqual(colony.SILENT, logging.CRITICAL + 1) + self.assertEqual(type(colony.SILENT), int) + + def test_silent_above_critical(self): + self.assertTrue(colony.SILENT > logging.CRITICAL) + + def test_trace_value(self): + self.assertEqual(colony.TRACE, 5) + self.assertEqual(colony.TRACE, logging.DEBUG - 5) + self.assertEqual(type(colony.TRACE), int) + + def test_trace_below_debug(self): + self.assertTrue(colony.TRACE < logging.DEBUG) + + def test_level_ordering(self): + self.assertTrue(colony.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 < colony.SILENT) + + def test_patch_logging(self): + colony.patch_logging() + + result = logging.getLevelName(colony.TRACE) + + self.assertEqual(result, "TRACE") + + def test_patch_logging_reverse(self): + colony.patch_logging() + + result = logging.getLevelName("TRACE") + + self.assertEqual(result, colony.TRACE) + + def test_patch_logging_idempotent(self): + colony.patch_logging() + colony.patch_logging() + + result = logging.getLevelName(colony.TRACE) + + self.assertEqual(result, "TRACE") + + def test_patch_logging_logger_trace(self): + colony.patch_logging() + + logger = logging.getLogger("colony.test.trace") + + self.assertTrue(hasattr(logger, "trace")) + self.assertTrue(callable(logger.trace)) + + def test_patch_logging_logger_trace_call(self): + colony.patch_logging() + + logger = logging.getLogger("colony.test.trace.call") + logger.setLevel(colony.TRACE) + records = [] + handler = logging.Handler() + handler.setLevel(colony.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, colony.TRACE) + self.assertEqual(records[0].levelname, "TRACE") + finally: + logger.removeHandler(handler) + + def test_patch_logging_logger_trace_filtered(self): + colony.patch_logging() + + logger = logging.getLogger("colony.test.trace.filtered") + logger.setLevel(logging.DEBUG) + records = [] + handler = logging.Handler() + handler.setLevel(colony.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) + + def test_get_level_int_trace(self): + result = colony.getLevelInt("TRACE") + + self.assertEqual(result, colony.TRACE) + self.assertEqual(result, 5) + + def test_get_level_int_silent(self): + result = colony.getLevelInt("SILENT") + + self.assertEqual(result, colony.SILENT) + self.assertEqual(result, 51) + + def test_get_level_name_trace(self): + result = colony.getLevelName("TRACE") + + self.assertEqual(result, loggers.TRACE) + + def test_get_level_name_silent(self): + result = colony.getLevelName("SILENT") + + self.assertEqual(result, loggers.SILENT) + + def test_dummy_logger_trace(self): + logger = colony.DummyLogger("test") + + self.assertTrue(hasattr(logger, "trace")) + self.assertTrue(callable(logger.trace)) + + # should not raise, just a no-op + logger.trace("test message") + def test_memory_handler(self): memory_handler = colony.MemoryHandler() formatter = logging.Formatter("%(message)s") diff --git a/src/colony_adm.py b/src/colony_adm.py index d483ec9b..d66928ca 100644 --- a/src/colony_adm.py +++ b/src/colony_adm.py @@ -590,7 +590,7 @@ def _generate_plugin(path, use_path=True): # filters the resources that have been gathered so that only the ones that # matter are defined in the structure and then creates the sequence of dependency # maps that are going to be defining the dependencies of the plugin - resources = _fitler_resources(resources) + resources = _filter_resources(resources) dependencies = [dependency.get_map() for dependency in plugin.dependencies] # creates the "final" plugin definition structure with the complete set of @@ -653,7 +653,7 @@ def _generate_config(path): output("Generating config descriptor for %s" % name) resources = _gather_config(path) - resources = _fitler_resources(resources) + resources = _filter_resources(resources) structure = dict( type="config", @@ -838,7 +838,7 @@ def _deploy(path, timestamp=None): # dumps the current descriptor object for the item that is going to be # deployed and then writes the contents of it into the info based file - # that is going to be used as a meta information provid3er + # that is going to be used as a meta information provider descriptor_s = json.dumps(descriptor) is_unicode = colony.legacy.is_unicode(descriptor_s) if is_unicode: @@ -1034,7 +1034,7 @@ def _upgrade(): # "calculates" both the path to the plugins directory and to the # meta information directory, both of them will be used to gather - # the information on the current instace's deployment + # the information on the current instance's deployment plugins_path = os.path.join(manager_path, "plugins") meta_path = os.path.join(manager_path, "meta") @@ -1230,7 +1230,7 @@ def _dependencies(info, upgrade=False): _install(id=dependency["id"], version=dependency["version"], upgrade=upgrade) -def _fitler_resources(resources, exclusion=(".pyc", ".temp", ".tmp")): +def _filter_resources(resources, exclusion=(".pyc", ".temp", ".tmp")): filtered = [] for resource in resources: if resource.endswith(exclusion):