Merge pull request #1529 from rmartin16/support-stdlib-logging

Capture logging for tools using stdlib logging

changes/1529.feature.rst

@@ -0,0 +1 @@
+GitPython's debug logging is now included in deep debug output.

src/briefcase/commands/base.py

@@ -13,7 +13,6 @@
 from pathlib import Path
 
 from cookiecutter import exceptions as cookiecutter_exceptions
-from cookiecutter.log import configure_logger as configure_cookiecutter_logger
 from cookiecutter.repository import is_repo_url
 from platformdirs import PlatformDirs
 
@@ -916,7 +915,7 @@ def generate_template(self, template, branch, output_path, extra_context):
             template=template, branch=branch
         )
 
-        configure_cookiecutter_logger("DEBUG" if self.logger.is_deep_debug else "INFO")
+        self.logger.configure_stdlib_logging("cookiecutter")
 
         try:
             # Unroll the template

src/briefcase/console.py

@@ -1,5 +1,6 @@
 from __future__ import annotations
 
+import logging
 import operator
 import os
 import platform
@@ -116,6 +117,25 @@ def export_log(cls):
         return cls.log.export_text()
 
 
+class RichLoggingStream:
+    """Stream for logging.StreamHandler that prints to console via debug logging."""
+
+    def __init__(self, logger: Log):
+        self.logger = logger
+
+    def write(self, msg: str) -> None:
+        self.logger.debug(msg)
+
+
+class RichLoggingHandler(logging.StreamHandler):
+    """A debug handler for third party tools using stdlib logging."""
+
+    def __init__(self, stream: RichLoggingStream):
+        super().__init__(stream=stream)
+        self.setLevel(logging.DEBUG)
+        self.setFormatter(logging.Formatter("%(levelname)s %(name)s: %(message)s"))
+
+
 class LogLevel(IntEnum):
     INFO = 0
     VERBOSE = 1
@@ -273,6 +293,31 @@ def is_deep_debug(self):
         """
         return self.verbosity >= LogLevel.DEEP_DEBUG
 
+    def configure_stdlib_logging(self, logger_name: str):
+        """Configure stdlib logging for a third party tool to log through Rich.
+
+        When a third party tool written in Python uses the stdlib logging for their
+        logging, it may provide an abstraction to enable the logging in the console or
+        may require a handler to be added externally. Either way, the default handler
+        to write to the console, i.e. logging.StreamHandler, will bypass Rich logging
+        and therefore not be included in the logfile. To avoid this issue, this will
+        add a handler that specifically writes to the console through Rich.
+
+        :param logger_name: Name of the logger the third party tool uses. Typically,
+            this is the package name or path to a submodule for the package. Since
+            logging uses namespaces for logging, enabling DEBUG logging for `git` will
+            also enable it for others like `git.cmd`, `git.remote`, `git.config`, etc.
+        """
+        if not self.is_deep_debug:
+            return
+
+        logger = logging.getLogger(logger_name)
+
+        # do not add another rich handler if one already exists
+        if not any(isinstance(h, RichLoggingHandler) for h in logger.handlers):
+            logger.addHandler(RichLoggingHandler(stream=RichLoggingStream(logger=self)))
+            logger.setLevel(logging.DEBUG)
+
     def capture_stacktrace(self, label="Main thread"):
         """Preserve Rich stacktrace from exception while in except block.
 

src/briefcase/integrations/git.py

@@ -72,5 +72,7 @@ def verify_install(cls, tools: ToolCache, **kwargs) -> ModuleType:
 """
                 ) from e
 
+        tools.logger.configure_stdlib_logging("git")
+
         tools.git = git
         return git

tests/commands/base/test_cookiecutter_logging.py

@@ -2,7 +2,7 @@
 
 import pytest
 
-from briefcase.console import LogLevel
+from briefcase.console import LogLevel, RichLoggingHandler
 
 cookiecutter_logger = logging.getLogger("cookiecutter")
 
@@ -16,24 +16,26 @@ def base_command(base_command):
 
 
 @pytest.mark.parametrize(
-    "verbosity, log_level",
+    "logging_level, handler_expected",
     [
-        (LogLevel.INFO, logging.INFO),
-        (LogLevel.DEBUG, logging.INFO),
-        (LogLevel.DEEP_DEBUG, logging.DEBUG),
+        (LogLevel.DEEP_DEBUG, True),
+        (LogLevel.DEBUG, False),
+        (LogLevel.VERBOSE, False),
+        (LogLevel.INFO, False),
     ],
 )
-def test_cookiecutter_logging_config(base_command, verbosity, log_level):
-    """The loggers for cookiecutter are configured as expected."""
-    base_command.logger.verbosity = verbosity
+def test_git_stdlib_logging(base_command, logging_level, handler_expected):
+    """A logging handler is configured for GitPython when DEEP_DEBUG is enabled."""
+    base_command.logger.verbosity = logging_level
 
     base_command.generate_template(
         template="", branch="", output_path="", extra_context={}
     )
-    # call multiple times to ensure only 1 handler ever exists
-    base_command.generate_template(
-        template="", branch="", output_path="", extra_context={}
+
+    assert handler_expected is any(
+        isinstance(h, RichLoggingHandler)
+        for h in logging.getLogger("cookiecutter").handlers
     )
 
-    assert len(cookiecutter_logger.handlers) == 1
-    assert cookiecutter_logger.handlers[0].level == log_level
+    # reset handlers since they are persistent
+    logging.getLogger("cookiecutter").handlers.clear()

tests/console/test_Log.py

@@ -1,13 +1,14 @@
 import datetime
+import logging
 from io import TextIOBase
-from unittest.mock import MagicMock, PropertyMock
+from unittest.mock import MagicMock, PropertyMock, call
 
 import pytest
 from rich.traceback import Trace
 
 import briefcase
 from briefcase.commands.dev import DevCommand
-from briefcase.console import Console, Log, LogLevel
+from briefcase.console import Console, Log, LogLevel, RichLoggingHandler
 from briefcase.exceptions import BriefcaseError
 
 TRACEBACK_HEADER = "Traceback (most recent call last)"
@@ -38,6 +39,14 @@ def command(mock_now, tmp_path) -> DevCommand:
     return command
 
 
+@pytest.fixture
+def logging_logger() -> logging.Logger:
+    logging_logger = logging.getLogger("test_pkg")
+    yield logging_logger
+    # reset handlers since they are persistent
+    logging_logger.handlers.clear()
+
+
 @pytest.mark.parametrize(
     "verbosity, verbose_enabled, debug_enabled, deep_debug_enabled",
     [
@@ -452,3 +461,50 @@ def test_log_error_with_context(capsys):
             "",
         ]
     )
+
+
+@pytest.mark.parametrize(
+    "logging_level, handler_expected",
+    [
+        (LogLevel.DEEP_DEBUG, True),
+        (LogLevel.DEBUG, False),
+        (LogLevel.VERBOSE, False),
+        (LogLevel.INFO, False),
+    ],
+)
+def test_stdlib_logging_config(logging_level, handler_expected, logging_logger):
+    """A logging handler is only added for DEEP_DEBUG mode."""
+    logger = Log(verbosity=logging_level)
+
+    logger.configure_stdlib_logging("test_pkg")
+
+    assert handler_expected is any(
+        isinstance(h, RichLoggingHandler) for h in logging_logger.handlers
+    )
+
+
+def test_stdlib_logging_only_one(logging_logger):
+    """Only one logging handler is ever created for a package."""
+    logger = Log(verbosity=LogLevel.DEEP_DEBUG)
+
+    logger.configure_stdlib_logging("test_pkg")
+    logger.configure_stdlib_logging("test_pkg")
+    logger.configure_stdlib_logging("test_pkg")
+
+    assert len(logging_logger.handlers) == 1
+
+
+def test_stdlib_logging_handler_writes_to_debug(logging_logger):
+    """The logging handler writes to the console through Log()."""
+    logger = Log(verbosity=LogLevel.DEEP_DEBUG)
+    logger.debug = MagicMock(wraps=logger.debug)
+
+    logger.configure_stdlib_logging("test_pkg")
+
+    logging_logger.debug("This is debug output")
+    logging_logger.info("This is info output")
+
+    assert logger.debug.mock_calls == [
+        call("DEBUG test_pkg: This is debug output\n"),
+        call("INFO test_pkg: This is info output\n"),
+    ]

tests/integrations/git/test_Git__verify.py

@@ -1,5 +1,8 @@
+import logging
+
 import pytest
 
+from briefcase.console import LogLevel, RichLoggingHandler
 from briefcase.exceptions import UnsupportedHostError
 from briefcase.integrations.git import Git
 
@@ -23,3 +26,26 @@ def test_unsupported_os(mock_tools):
         match=f"{Git.name} is not supported on wonky",
     ):
         Git.verify(mock_tools)
+
+
+@pytest.mark.parametrize(
+    "logging_level, handler_expected",
+    [
+        (LogLevel.DEEP_DEBUG, True),
+        (LogLevel.DEBUG, False),
+        (LogLevel.VERBOSE, False),
+        (LogLevel.INFO, False),
+    ],
+)
+def test_git_stdlib_logging(mock_tools, logging_level, handler_expected):
+    """A logging handler is configured for GitPython when DEEP_DEBUG is enabled."""
+    mock_tools.logger.verbosity = logging_level
+
+    Git.verify(mock_tools)
+
+    assert handler_expected is any(
+        isinstance(h, RichLoggingHandler) for h in logging.getLogger("git").handlers
+    )
+
+    # reset handlers since they are persistent
+    logging.getLogger("git").handlers.clear()