Repository: databrickslabs/blueprint

Issue:
[BUG]: Colorised logs don't interpolate `%`-arguments
The logging system supports lazy-formatting of messages by supporting `%`-style placeholders for arguments, provided as additional arguments on the call. For example:
```python
logger.critical("The reactor will explode in %d minute(s).", 1)
```
(The message is only rendered if the log message needs to actually be emitted.)

Currently the logging configuration set up by Blueprint doesn't support this if colorised output is enabled. (When disabled, they render correctly.) Although in our applications we tend to use f-style strings, libraries that we use don't and the logs often contain only the placeholders with the arguments lost.

The logging set up by Blueprint needs to be fixed so that messages of this style are correctly rendered.

The current situation leading to this is:

 - In the Python logging system, formatters are responsible for interpolating arguments into the message.
 - The `NiceFormatter` doesn't do this when colorised output is enabled.

Discussion:

Solution patch:
diff --git a/src/databricks/labs/blueprint/logger.py b/src/databricks/labs/blueprint/logger.py
index 13e73d9..848590a 100644
--- a/src/databricks/labs/blueprint/logger.py
+++ b/src/databricks/labs/blueprint/logger.py
@@ -30,7 +30,7 @@ class NiceFormatter(logging.Formatter):
             stream: the output stream to which the formatter will write, used to check if it is a console.
             probe_tty: If true, the formatter will enable color support if the output stream appears to be a console.
         """
-        super().__init__(fmt="%(asctime)s %(levelname)s [%(name)s] %(message)s", datefmt="%H:%M")
+        super().__init__(fmt="%(asctime)s %(levelname)s [%(name)s] %(message)s", datefmt="%H:%M:%S")
         self._levels = {
             logging.NOTSET: self._bold("TRACE"),
             logging.DEBUG: self._bold(f"{self.CYAN}DEBUG"),
@@ -56,7 +56,7 @@ class NiceFormatter(logging.Formatter):
         module_split = record.name.split(".")
         last_two_modules = len(module_split) - 2
         name = ".".join(part if i >= last_two_modules else part[0] for i, part in enumerate(module_split))
-        msg = record.msg
+        msg = record.getMessage()
         if record.exc_info and not record.exc_text:
             record.exc_text = self.formatException(record.exc_info)
         if record.exc_text:


Test patch:
diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py
index 989b2f3..ba8f69e 100644
--- a/tests/unit/test_logger.py
+++ b/tests/unit/test_logger.py
@@ -203,16 +203,7 @@ def test_formatter_format_simple_msg(use_colors: bool) -> None:
     assert stripped.endswith(" This is a test message.")
 
 
-@pytest.mark.parametrize(
-    "use_colors",
-    (
-        pytest.param(
-            True, marks=pytest.mark.xfail(reason="Argument interpolation when colorizing doesn't work.", strict=True)
-        ),
-        False,
-    ),
-    ids=("with_colors", "without_colors"),
-)
+@pytest.mark.parametrize("use_colors", (True, False), ids=("with_colors", "without_colors"))
 def test_formatter_format_msg_with_args(use_colors: bool) -> None:
     """Ensure the formatter correctly formats a message with arguments that need to be interpolated."""
     formatter = NiceFormatter()
@@ -226,17 +217,7 @@ def test_formatter_format_msg_with_args(use_colors: bool) -> None:
     assert stripped.endswith(" This is a test message with 2 arguments.")
 
 
-@pytest.mark.parametrize(
-    "use_colors",
-    (
-        True,
-        pytest.param(
-            False,
-            marks=pytest.mark.xfail(reason="Non-colorized logs currently missing second-granularity.", strict=True),
-        ),
-    ),
-    ids=["with_colors", "without_colors"],
-)
+@pytest.mark.parametrize("use_colors", (True, False), ids=["with_colors", "without_colors"])
 def test_formatter_timestamp(use_colors: bool) -> None:
     """Ensure the formatter starts with the timestamp."""
     formatter = NiceFormatter()