Merge pull request #122 from MScottBlake/improve-logging

Add recipe name context and color to log entries

Author: MScottBlake

pyproject.toml

@@ -17,7 +17,7 @@ dev = [
 
 [project]
 name = "cloud-autopkg-runner"
-version = "0.24.2"
+version = "0.24.3"
 description = "A Python library designed to level-up your AutoPkg automations with a focus on CI/CD performance."
 readme = { file = "README.md", content-type = "text/markdown" }
 requires-python = ">=3.10"

src/cloud_autopkg_runner/__init__.py

@@ -21,6 +21,7 @@
 from .recipe import Recipe
 from .recipe_finder import RecipeFinder
 from .recipe_report import RecipeReport
+from . import logging_config
 
 __all__ = [
     "AutoPkgPrefs",
@@ -31,3 +32,6 @@
     "Settings",
     "get_cache_plugin",
 ]
+
+# Library-level logger
+logger = logging_config.get_logger(__name__)

src/cloud_autopkg_runner/__main__.py

@@ -45,8 +45,11 @@
     InvalidJsonContents,
     RecipeException,
 )
+from cloud_autopkg_runner.logging_context import recipe_context
 from cloud_autopkg_runner.recipe_report import ConsolidatedReport
 
+logger = logging_config.get_logger(__name__)
+
 T = TypeVar("T")
 
 # Constant that indicates a worker queue is empty and can be stopped
@@ -127,7 +130,6 @@ async def _create_recipe(
         recipe_path = await _get_recipe_path(recipe_name, autopkg_prefs)
         return Recipe(recipe_path, report_dir, autopkg_prefs)
     except (InvalidFileContents, RecipeException):
-        logger = logging_config.get_logger(__name__)
         logger.exception("Failed to create `Recipe` object: %s", recipe_name)
         return None
 
@@ -154,7 +156,6 @@ def _generate_recipe_list(args: Namespace) -> set[str]:
         InvalidJsonContents: If the JSON file specified by `args.recipe_list`
             contains invalid JSON, indicating a malformed input file.
     """
-    logger = logging_config.get_logger(__name__)
     logger.debug("Generating recipe list...")
 
     output: set[str] = set()
@@ -344,7 +345,6 @@ async def _process_recipe_list(
     Returns:
         A dictionary of recipe names mapped to their reports.
     """
-    logger = logging_config.get_logger(__name__)
     settings = Settings()
 
     num_workers = min(settings.max_concurrency, _count_iterable(recipe_list))
@@ -388,12 +388,15 @@ async def _recipe_worker(
     every recipe name retrieved from the queue, the worker performs the full
     execution lifecycle:
 
-    1.  Resolve the recipe path and construct a `Recipe` instance. Invalid or
+    1.  Set the per-task logging context (`recipe_context`) so all log output is
+        tagged with the active recipe name.
+    2.  Resolve the recipe path and construct a `Recipe` instance. Invalid or
         unreadable recipes are logged and skipped without terminating the worker.
-    2.  Execute the recipe with a timeout using `asyncio.wait_for()`, capturing the
+    3.  Execute the recipe with a timeout using `asyncio.wait_for()`, capturing the
         resulting `ConsolidatedReport` on success.
-    3.  Handle and log timeouts and unexpected exceptions without interrupting
+    4.  Handle and log timeouts and unexpected exceptions without interrupting
         other workers.
+    5.  Reset the logging context and mark the queue item as processed.
 
     The worker returns a mapping of recipe names to their final `ConsolidatedReport`
     objects. Multiple workers may run concurrently; their partial result maps are
@@ -415,7 +418,6 @@ async def _recipe_worker(
         Exception: Any unexpected error inside the worker is logged and re-raised
             to allow the caller to fail fast, while still ensuring proper cleanup.
     """
-    logger = logging_config.get_logger(__name__)
     results: dict[str, ConsolidatedReport] = {}
 
     while True:
@@ -424,6 +426,7 @@ async def _recipe_worker(
             queue.task_done()
             break
 
+        token = recipe_context.set(recipe_name)
         try:
             logger.info("Starting recipe %s", recipe_name)
 
@@ -453,6 +456,7 @@ async def _recipe_worker(
             raise
         finally:
             queue.task_done()
+            recipe_context.reset(token)
 
     return results
 
@@ -471,7 +475,6 @@ def _signal_handler(sig: int, _frame: FrameType | None) -> NoReturn:
         _frame: The current stack frame object, which is typically unused in
             simple signal handlers and thus ignored.
     """
-    logger = logging_config.get_logger(__name__)
     logger.error("Signal %s received. Exiting...", sig)
     sys.exit(0)
 

src/cloud_autopkg_runner/logging_config.py

@@ -5,15 +5,65 @@
 destinations (console and/or file). It also offers a convenient way to
 retrieve logger instances for use in other modules.
 
-Functions:
-    initialize_logger: Initializes the logging system with a console handler
-        and an optional file handler.
-    get_logger: Retrieves a logger instance with the specified name.
+The logging system is enhanced with recipe-level contextual information.
+When the caller sets the context variable in cloud_autopkg_runner.logging_context,
+every log line automatically includes the recipe name, even when running concurrently.
 """
 
 import logging
 import sys
-from typing import TextIO
+from typing import ClassVar, TextIO
+
+from cloud_autopkg_runner.logging_context import recipe_context
+
+
+class ColorFormatter(logging.Formatter):
+    """Add ANSI coloring to log level names while preserving padding."""
+
+    COLORS: ClassVar[dict[str, str]] = {
+        "DEBUG": "\033[36m",  # Cyan
+        "INFO": "\033[32m",  # Green
+        "WARNING": "\033[33m",  # Yellow
+        "ERROR": "\033[31m",  # Red
+        "CRITICAL": "\033[41m",  # Red background
+    }
+    RESET: ClassVar[str] = "\033[0m"
+
+    def format(self, record: logging.LogRecord) -> str:
+        """Render log message with colorized level names."""
+        # Let the base class format the record first
+        msg = super().format(record)
+
+        color = self.COLORS.get(record.levelname)
+        if not color:
+            return msg
+
+        # Replace the exact (already padded) level text inside msg
+        padded = f"{record.levelname:<7}"
+        colored = f"{color}{padded}{self.RESET}"
+
+        return msg.replace(padded, colored, 1)
+
+
+class RecipeContextFilter(logging.Filter):
+    """Inject contextual recipe information into every log record."""
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        """Add the current recipe context to the log record.
+
+        This method is called for each log record emitted. It sets
+        `record.recipe` to the value stored in the recipe_context
+        ContextVar, or "-" if the context variable is not set.
+
+        Returns:
+            True always, so that the record is not filtered out.
+        """
+        try:
+            record.recipe = recipe_context.get()
+        except LookupError:
+            record.recipe = __package__
+
+        return True
 
 
 def initialize_logger(verbosity_level: int, log_file: str | None = None) -> None:
@@ -24,6 +74,9 @@ def initialize_logger(verbosity_level: int, log_file: str | None = None) -> None
     `verbosity_level` argument, while the file handler (if enabled) logs at
     the DEBUG level.
 
+    A logging Filter is added that inserts the current recipe context
+    (if set) into each log record as `%(recipe)s`.
+
     Args:
         verbosity_level: An integer representing the verbosity level.  Maps to
             logging levels as follows:
@@ -32,11 +85,11 @@ def initialize_logger(verbosity_level: int, log_file: str | None = None) -> None
             will be written to this file in addition to the console. If None,
             no file logging will occur.
     """
-    logger = logging.getLogger()
+    logger = logging.getLogger(__name__.split(".")[0])
     logger.setLevel(logging.DEBUG)
-
     logger.handlers.clear()
 
+    # Map verbosity flags to log levels
     log_levels: list[int] = [
         logging.ERROR,
         logging.WARNING,
@@ -45,24 +98,28 @@ def initialize_logger(verbosity_level: int, log_file: str | None = None) -> None
     ]
     level: int = log_levels[min(verbosity_level, len(log_levels) - 1)]
 
+    # Attach recipe context filter
+    context_filter = RecipeContextFilter()
+    logger.addFilter(context_filter)
+
     # Console handler
     console_handler: logging.StreamHandler[TextIO] = logging.StreamHandler(sys.stdout)
     console_handler.setLevel(level)
-    console_formatter: logging.Formatter = logging.Formatter(
-        "%(module)-20s %(levelname)-8s %(message)s"
-    )
+    console_formatter = ColorFormatter("%(levelname)-7s %(recipe)-25s %(message)s")
     console_handler.setFormatter(console_formatter)
+    console_handler.addFilter(context_filter)
     logger.addHandler(console_handler)
 
     # File handler (optional)
     if log_file:
         file_handler: logging.FileHandler = logging.FileHandler(log_file, mode="w")
         file_handler.setLevel(logging.DEBUG)
         file_formatter: logging.Formatter = logging.Formatter(
-            "%(asctime)s %(module)-20s %(levelname)-8s %(message)s",
+            "%(asctime)s %(levelname)-7s %(recipe)-25s %(message)s",
             datefmt="%m-%d %H:%M",
         )
         file_handler.setFormatter(file_formatter)
+        file_handler.addFilter(context_filter)
         logger.addHandler(file_handler)
 
 
@@ -73,6 +130,13 @@ def get_logger(name: str) -> logging.Logger:
     simplifies the process of obtaining loggers for use in different
     modules of the application.
 
+    This wrapper allows for future enhancements, such as adding context
+    filters or structured logging.
+
+    This does not configure handlers or log levels; it simply returns
+    the logger with the given name. Use `initialize_logger()` at
+    application startup to configure logging output.
+
     Args:
         name: The name of the logger to retrieve (typically `__name__`).
 

src/cloud_autopkg_runner/logging_context.py

@@ -0,0 +1,15 @@
+"""Provides a context variable for logging recipe-specific information.
+
+This module defines a ContextVar that stores the currently executing
+recipe name. Logging filters can read this variable to automatically
+tag log messages with the correct recipe context, even in concurrent
+async execution.
+
+Usage:
+    from cloud_autopkg_runner.logging_context import recipe_context
+    recipe_context.set("MyRecipe.pkg.recipe")
+"""
+
+import contextvars
+
+recipe_context = contextvars.ContextVar("recipe", default=__package__)

tests/unit/test___main__.py

@@ -234,15 +234,12 @@ async def test_create_recipe_invalid_file_contents(
 ) -> None:
     """Should return None and log an error on InvalidFileContents."""
     with (
-        patch("cloud_autopkg_runner.logging_config.get_logger") as mock_get_logger,
+        patch("cloud_autopkg_runner.__main__.logger") as mock_logger,
         patch(
             "cloud_autopkg_runner.recipe.Recipe",
             side_effect=InvalidFileContents("corrupt recipe file"),
         ),
     ):
-        mock_logger = MagicMock()
-        mock_get_logger.return_value = mock_logger
-
         result = await _create_recipe("bad_recipe", tmp_path, mock_autopkg_prefs)
 
         mock_logger.exception.assert_called_once_with(
@@ -257,15 +254,12 @@ async def test_create_recipe_recipe_exception(
 ) -> None:
     """Should return None and log an error on RecipeException."""
     with (
-        patch("cloud_autopkg_runner.logging_config.get_logger") as mock_get_logger,
+        patch("cloud_autopkg_runner.__main__.logger") as mock_logger,
         patch(
             "cloud_autopkg_runner.recipe.Recipe",
             side_effect=RecipeException("missing processor"),
         ),
     ):
-        mock_logger = MagicMock()
-        mock_get_logger.return_value = mock_logger
-
         result = await _create_recipe("exception_recipe", tmp_path, mock_autopkg_prefs)
 
         mock_logger.exception.assert_called_once_with(
@@ -385,12 +379,8 @@ async def test_recipe_worker_timeout_logged(tmp_path: Path) -> None:
     mock_settings.recipe_timeout = 3
     mock_settings.report_dir = tmp_path
 
-    mock_logger = MagicMock()
-
     with (
-        patch(
-            "cloud_autopkg_runner.logging_config.get_logger", return_value=mock_logger
-        ),
+        patch("cloud_autopkg_runner.__main__.logger") as mock_logger,
         patch(
             "cloud_autopkg_runner.__main__._create_recipe",
             new=AsyncMock(return_value=mock_recipe),

tests/unit/test_logging_config.py

@@ -18,7 +18,7 @@
 def test_console_handler_levels(verbosity_level: int, expected_level: int) -> None:
     """Test that verbosity levels are set correctly."""
     logging_config.initialize_logger(verbosity_level=verbosity_level, log_file=None)
-    logger = logging.getLogger()
+    logger = logging.getLogger("cloud_autopkg_runner")
 
     # Get the most recent StreamHandler (console handler)
     console_handler = next(
@@ -37,7 +37,7 @@ def test_logs_to_console_but_not_file(tmp_path: Path) -> None:
 
     # Initialize logger with no file output
     logging_config.initialize_logger(verbosity_level=1, log_file=None)
-    logger = logging.getLogger()
+    logger = logging.getLogger("cloud_autopkg_runner")
 
     # Assert no file handler was added (log file should not exist)
     file_handler = next(
@@ -54,7 +54,7 @@ def test_logs_to_file(tmp_path: Path) -> None:
     log_file = tmp_path / "test.log"
 
     logging_config.initialize_logger(verbosity_level=1, log_file=str(log_file))
-    logger = logging.getLogger()
+    logger = logging.getLogger("cloud_autopkg_runner")
 
     logger.info("This should go to both console and file")