Repository: beeware/briefcase
Pull request #1470 (2023-09-29 17:53:26)

Enable debug cookiecutter logging for deep debug
## Changes
- Configure logging for cookiecutter before generating a template via [`cookiecutter.log.configure_logger()`](https://github.com/cookiecutter/cookiecutter/blob/24020484395f3962156dfcee5e9e1d6f2013da07/cookiecutter/log.py#L19)
- This enables cookiecutter's debug output when Briefcase's "deep debug" is enabled via `-vv`
- The changenote is `misc` since we already have a `feature` note for the addition of `-vv` support

## Notes
- cookiecutter uses the notorious `logging` package for its logging
  - By default, it appears that cookiecutter [only configures](https://github.com/search?q=repo%3Acookiecutter%2Fcookiecutter%20configure_logger&type=code) logging handlers for its logging when using its CLI; therefore, cookiecutter doesn't enable any handlers for its logger when Briefcase generates a template.
  - Although, perhaps notably, they also don't configure a `NullHandler` by default....so, cookiecutter is likely to be subjected to a default handler if one is configured....but such is the life of using `logging`...
  - At any rate, since no handlers were configured before, this changes cookiecutter logging to output `INFO` and above by default.
  - Although, cookiecutter only appears to use `logger.debug()` and `logger.error()` right now...so, it shouldn't matter in reality.
  - Finally, cookiecutter deletes any existing handlers when `configure_logger()` is called....so, it is safe to call multiple times without concerns about duplicating handlers for the logger.
- Additionally, I couldn't call `configure_logger()` in `BaseCommand.__init__()` because `verbosity` won't be set until `parse_options()` is called...and `verbosity` can technically change (although, it doesn't currently).

## PR Checklist:
<!--- Go over all the following points, and put an `x` in all the boxes that apply. -->
- [X] All new features have been tested
- [X] All new features have been documented
- [X] I have read the **CONTRIBUTING.md** file
- [X] I will abide by the code of conduct



Patch:
diff --git a/changes/1470.misc.rst b/changes/1470.misc.rst
new file mode 100644
index 00000000..6b016925
--- /dev/null
+++ b/changes/1470.misc.rst
@@ -0,0 +1,1 @@
+Cookiecutter's debug logging is now enabled when deep debug is activated via ``-vv``.
diff --git a/src/briefcase/commands/base.py b/src/briefcase/commands/base.py
index 7125f1d2..86a180f8 100644
--- a/src/briefcase/commands/base.py
+++ b/src/briefcase/commands/base.py
@@ -13,6 +13,7 @@ from argparse import RawDescriptionHelpFormatter
 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
 
@@ -911,6 +912,8 @@ Did you run Briefcase in a project directory that contains {filename.name!r}?"""
             template=template, branch=branch
         )
 
+        configure_cookiecutter_logger("DEBUG" if self.logger.is_deep_debug else "INFO")
+
         try:
             # Unroll the template
             self.tools.cookiecutter(


Test patch:
diff --git a/tests/commands/base/test_cookiecutter_logging.py b/tests/commands/base/test_cookiecutter_logging.py
new file mode 100644
index 00000000..34be8b83
--- /dev/null
+++ b/tests/commands/base/test_cookiecutter_logging.py
@@ -0,0 +1,37 @@
+import logging
+
+import pytest
+
+cookiecutter_logger = logging.getLogger("cookiecutter")
+
+
+@pytest.fixture
+def base_command(base_command):
+    # Mock actual templating commands as no-ops
+    base_command.update_cookiecutter_cache = lambda *a, **kw: None
+    base_command.tools.cookiecutter = lambda *a, **kw: None
+    return base_command
+
+
+@pytest.mark.parametrize(
+    "verbosity, log_level",
+    [
+        (0, logging.INFO),
+        (1, logging.INFO),
+        (2, logging.DEBUG),
+    ],
+)
+def test_cookiecutter_logging_config(base_command, verbosity, log_level):
+    """The loggers for cookiecutter are configured as expected."""
+    base_command.logger.verbosity = verbosity
+
+    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 len(cookiecutter_logger.handlers) == 1
+    assert cookiecutter_logger.handlers[0].level == log_level