From b5b7082069756cc151ffbfc3520263684b479a21 Mon Sep 17 00:00:00 2001 From: Russell Martin Date: Tue, 7 Nov 2023 14:43:23 -0500 Subject: [PATCH] Capture logging for tools using stdlib logging --- changes/1529.feature.rst | 1 + src/briefcase/commands/base.py | 3 +- src/briefcase/console.py | 45 ++++++++++++++ src/briefcase/integrations/git.py | 2 + .../base/test_cookiecutter_logging.py | 28 +++++---- tests/console/test_Log.py | 60 ++++++++++++++++++- tests/integrations/git/test_Git__verify.py | 26 ++++++++ 7 files changed, 148 insertions(+), 17 deletions(-) create mode 100644 changes/1529.feature.rst diff --git a/changes/1529.feature.rst b/changes/1529.feature.rst new file mode 100644 index 000000000..e449b293f --- /dev/null +++ b/changes/1529.feature.rst @@ -0,0 +1 @@ +GitPython's debug logging is now included in deep debug output. diff --git a/src/briefcase/commands/base.py b/src/briefcase/commands/base.py index 2f87eed9d..9c511c18a 100644 --- a/src/briefcase/commands/base.py +++ b/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 diff --git a/src/briefcase/console.py b/src/briefcase/console.py index 3b6c6a139..c1481ddb5 100644 --- a/src/briefcase/console.py +++ b/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. diff --git a/src/briefcase/integrations/git.py b/src/briefcase/integrations/git.py index 2374a6d38..55b83c59f 100644 --- a/src/briefcase/integrations/git.py +++ b/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 diff --git a/tests/commands/base/test_cookiecutter_logging.py b/tests/commands/base/test_cookiecutter_logging.py index 45f58cb2e..acdd70abe 100644 --- a/tests/commands/base/test_cookiecutter_logging.py +++ b/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() diff --git a/tests/console/test_Log.py b/tests/console/test_Log.py index af0cf858b..8b3259fa8 100644 --- a/tests/console/test_Log.py +++ b/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"), + ] diff --git a/tests/integrations/git/test_Git__verify.py b/tests/integrations/git/test_Git__verify.py index 8e7accfc1..0a8e6ae08 100644 --- a/tests/integrations/git/test_Git__verify.py +++ b/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()