Repository: databrickslabs/blueprint

Issue:
[BUG]: Blueprint applications launched with `--debug` do not automatically have `DEBUG` logging enabled
The CLI pattern enabled by `App` doesn't properly propagate the log-level from the command payload into the logging system. This means that the `--debug` flag doesn't enable `DEBUG` logging, which is its intent.

The current situation is that:

 - The `App` plumbing does extract the intended log-level, and set it on the `databricks` logger.
 - The `App` plumbing also installs the custom logging handler on the root logger.
 - The root log-level is left as-is. (It defaults to `WARNING`).
 - The attached handler is set to handle anything at `DEBUG` or higher.
 - The _application_ logger (which is typically under `databricks.labs.[…]`) has its level set:

    - If the app seems to be running within an IDE-based launcher (`is_in_debug()`): `DEBUG`
    - Otherwise: `INFO`

Crucially, even though the `databricks` logger has been set to `DEBUG`, the application logger (a child) is set to `INFO` and `DEBUG`-level logs will be dropped there, never propagating up to the root or the attached custom handler.

Discussion:

Solution patch:
diff --git a/src/databricks/labs/blueprint/entrypoint.py b/src/databricks/labs/blueprint/entrypoint.py
index 792848a..3489332 100644
--- a/src/databricks/labs/blueprint/entrypoint.py
+++ b/src/databricks/labs/blueprint/entrypoint.py
@@ -8,7 +8,7 @@ from pathlib import Path
 from databricks.labs.blueprint.logger import install_logger
 
 
-def get_logger(__file: str):
+def get_logger(__file: str, *, manager: logging.Manager = logging.Logger.manager) -> logging.Logger:
     """Used as `get_logger(__file__)` to return a relevant logger for a file"""
     project_root = find_project_root(__file).absolute()
     entrypoint = Path(__file).absolute()
@@ -21,12 +21,10 @@ def get_logger(__file: str):
     relative = relative.removesuffix(".py")
     module_name = relative.replace(os.sep, ".")
 
-    logger = logging.getLogger(module_name)
+    logger = manager.getLogger(module_name)
 
-    level = "INFO"
     if is_in_debug():
-        level = "DEBUG"
-    logger.setLevel(level)
+        logger.setLevel(logging.DEBUG)
 
     return logger
 


Test patch:
diff --git a/tests/unit/test_entrypoint.py b/tests/unit/test_entrypoint.py
index a371a55..449a1bb 100644
--- a/tests/unit/test_entrypoint.py
+++ b/tests/unit/test_entrypoint.py
@@ -1,11 +1,14 @@
 import inspect
+import logging
 from pathlib import Path
 from unittest.mock import MagicMock
 
 import pytest
 
+import databricks.labs.blueprint.entrypoint as entrypoint
 from databricks.labs.blueprint.entrypoint import (
     find_project_root,
+    get_logger,
     relative_paths,
     run_main,
 )
@@ -40,3 +43,40 @@ def test_run_main():
     main = MagicMock()
     run_main(main)
     main.assert_called_once()
+
+
+def test_get_logger_name() -> None:
+    """Ensure the logger name is set to something module-like, even if the file is a script/path."""
+    # File is something like /path/to/blueprint/tests/unit/test_entrypoint.py
+    logger = get_logger(__file__)
+
+    assert logger.name == "tests.unit.test_entrypoint"
+
+
+@pytest.fixture
+def log_manager() -> logging.Manager:
+    """Logging manager, independent of the system logging."""
+    root = logging.RootLogger(logging.WARNING)
+    return logging.Manager(root)
+
+
+def test_get_logger_when_in_debug(monkeypatch, log_manager: logging.Manager) -> None:
+    """When in debug mode, the logger is hardcoded to DEBUG level."""
+    monkeypatch.setattr(entrypoint, "is_in_debug", lambda: True)
+
+    # Ensure we don't get a cached logger that has already been configured to a level.
+    logger = get_logger(__file__, manager=log_manager)
+
+    assert logger.level == logging.DEBUG
+    assert logger.propagate is True
+
+
+def test_get_logger_when_not_in_debug(monkeypatch, log_manager: logging.Manager) -> None:
+    """When in not in debug mode, the logger should simply propagate to the parent."""
+    monkeypatch.setattr(entrypoint, "is_in_debug", lambda: False)
+
+    # Ensure we don't get a cached logger that has already been configured to a level.
+    logger = get_logger(__file__, manager=log_manager)
+
+    assert logger.level == logging.NOTSET
+    assert logger.propagate is True