Refactor handling of error raised for missing formatting keys

The former error message was a bit misleading for cases where the
KeyError originates from a missing nested key (e.g. "extra[missing]").
The message was changed to something more generic.

The error type was also changed to `ValueError` since `KeyError` is
usually expected to only contain the missing key, not a verbose message.

Scope of the `try / catch` was reduced to only wrap the `format_map()`
function.

Tests were extended to cover all branches.

Author: Delgan

loguru/_handler.py

@@ -158,11 +158,11 @@ def emit(self, record, level_id, from_decorator, is_raw, colored_message):
             elif self._is_formatter_dynamic:
                 if not self._colorize:
                     precomputed_format = self._memoize_dynamic_format(dynamic_format)
-                    formatted = precomputed_format.format_map(formatter_record)
+                    formatted = self._format_record(precomputed_format, formatter_record)
                 elif colored_message is None:
                     ansi_level = self._levels_ansi_codes[level_id]
                     _, precomputed_format = self._memoize_dynamic_format(dynamic_format, ansi_level)
-                    formatted = precomputed_format.format_map(formatter_record)
+                    formatted = self._format_record(precomputed_format, formatter_record)
                 else:
                     ansi_level = self._levels_ansi_codes[level_id]
                     formatter, precomputed_format = self._memoize_dynamic_format(
@@ -172,24 +172,24 @@ def emit(self, record, level_id, from_decorator, is_raw, colored_message):
                         record["message"], ansi_level=ansi_level, colored_message=colored_message
                     )
                     formatter_record["message"] = coloring_message
-                    formatted = precomputed_format.format_map(formatter_record)
+                    formatted = self._format_record(precomputed_format, formatter_record)
 
             else:
                 if not self._colorize:
                     precomputed_format = self._decolorized_format
-                    formatted = precomputed_format.format_map(formatter_record)
+                    formatted = self._format_record(precomputed_format, formatter_record)
                 elif colored_message is None:
                     ansi_level = self._levels_ansi_codes[level_id]
                     precomputed_format = self._precolorized_formats[level_id]
-                    formatted = precomputed_format.format_map(formatter_record)
+                    formatted = self._format_record(precomputed_format, formatter_record)
                 else:
                     ansi_level = self._levels_ansi_codes[level_id]
                     precomputed_format = self._precolorized_formats[level_id]
                     coloring_message = self._formatter.make_coloring_message(
                         record["message"], ansi_level=ansi_level, colored_message=colored_message
                     )
                     formatter_record["message"] = coloring_message
-                    formatted = precomputed_format.format_map(formatter_record)
+                    formatted = self._format_record(precomputed_format, formatter_record)
 
             if self._serialize:
                 formatted = self._serialize_record(formatted, record)
@@ -204,10 +204,6 @@ def emit(self, record, level_id, from_decorator, is_raw, colored_message):
                     self._queue.put(str_record)
                 else:
                     self._sink.write(str_record)
-        except KeyError as e:
-            if not self._error_interceptor.should_catch():
-                raise self._make_key_error(e, record) from e
-            self._error_interceptor.print(record, exception=self._make_key_error(e, record))
         except Exception:
             if not self._error_interceptor.should_catch():
                 raise
@@ -248,22 +244,25 @@ def update_format(self, level_id):
         ansi_code = self._levels_ansi_codes[level_id]
         self._precolorized_formats[level_id] = self._formatter.colorize(ansi_code)
 
-    @staticmethod
-    def _make_key_error(original, record):
-        key = original.args[0] if original.args else "?"
-        available = ", ".join(sorted(record.keys()))
-        message = (
-            "The format string references an unknown key '%s'. "
-            "Available record keys are: %s. "
-            "To include custom data, use 'logger.bind(key=value)' and reference it "
-            "as '{extra[key]}' in the format string." % (key, available)
-        )
-        return KeyError(message)
-
     @property
     def levelno(self):
         return self._levelno
 
+    @staticmethod
+    def _format_record(log_format, record):
+        try:
+            return log_format.format_map(record)
+        except KeyError as e:
+            available = ", ".join(map(repr, record.keys()))
+            raise ValueError(
+                "Failed to format log record: key %s not found.\n"
+                "Verify that the format string %r only references valid record keys "
+                "and that all required extra keys are present.\n"
+                "Available records key are: %s.\n"
+                "To include custom data, use `logger.bind(key=value)` and reference it "
+                "as '{extra[key]}' in the format string." % (e, log_format, available)
+            ) from e
+
     @staticmethod
     def _serialize_record(text, record):
         exception = record["exception"]

tests/test_add_option_format.py

@@ -85,40 +85,3 @@ def __format__(self, spec):
 def test_invalid_format_builtin(writer):
     with pytest.raises(ValueError, match=r".* most likely a mistake"):
         logger.add(writer, format=format)
-
-
-def test_invalid_format_key_emits_helpful_error_with_catch(capsys):
-    logger.add(lambda msg: None, format="{nonexistent}", catch=True)
-    logger.info("Hello")
-    stderr = capsys.readouterr().err
-    assert "nonexistent" in stderr
-    assert "logger.bind(key=value)" in stderr
-    assert "extra[key]" in stderr
-    # Check that available record keys are listed
-    for key in ["elapsed", "exception", "extra", "file", "level", "message"]:
-        assert key in stderr
-
-
-def test_invalid_format_key_raises_enhanced_error_without_catch():
-    logger.add(lambda msg: None, format="{nonexistent}", catch=False)
-    with pytest.raises(KeyError, match=r"nonexistent"):
-        logger.info("Hello")
-
-
-def test_invalid_format_key_error_message_content():
-    logger.add(lambda msg: None, format="{bogus_key}", catch=False)
-    with pytest.raises(KeyError, match=r"logger\.bind") as exc_info:
-        logger.info("Hello")
-    error_message = str(exc_info.value)
-    assert "bogus_key" in error_message
-    assert "extra[key]" in error_message
-
-
-def test_patcher_added_keys_work_in_format(writer):
-    def patcher(record):
-        record["my_value"] = 42
-
-    logger.add(writer, format="{message} | {my_value}")
-    logger.configure(patcher=patcher)
-    logger.info("Hello")
-    assert "Hello | 42" in writer.read()

tests/test_configure.py

@@ -138,7 +138,7 @@ def test_reset_previous_extra(writer):
 
     logger.configure(extra={})
 
-    with pytest.raises(KeyError):
+    with pytest.raises(ValueError, match=r"Failed to format log record: key 'a' not found."):
         logger.debug("Nope")
 
 
@@ -148,7 +148,7 @@ def test_reset_previous_patcher(writer):
 
     logger.configure(patcher=lambda r: None)
 
-    with pytest.raises(KeyError):
+    with pytest.raises(ValueError, match=r"Failed to format log record: key 'a' not found."):
         logger.debug("Nope")
 
 

tests/test_formatting.py

@@ -246,3 +246,23 @@ def test_invalid_color_markup(writer):
         ValueError, match=r"^Invalid format, color markups could not be parsed correctly$"
     ):
         logger.add(writer, format="<red>Not closed tag", colorize=True)
+
+
+@pytest.mark.parametrize("format_", ["{missing}", lambda _: "{missing}\n"])
+@pytest.mark.parametrize("colorize", [True, False])
+@pytest.mark.parametrize("colors", [True, False])
+def test_invalid_format_key_emits_helpful_error_with_catch(capsys, format_, colorize, colors):
+    logger.add(lambda msg: None, format=format_, catch=True, colorize=colorize)
+    logger.opt(colors=colors).info("Hello")
+    out, err = capsys.readouterr()
+    assert out == ""
+    assert "ValueError: Failed to format log record: key 'missing' not found" in err
+
+
+@pytest.mark.parametrize("format_", ["{missing}", lambda _: "{missing}\n"])
+@pytest.mark.parametrize("colorize", [True, False])
+@pytest.mark.parametrize("colors", [True, False])
+def test_invalid_format_key_raises_enhanced_error_without_catch(format_, colorize, colors):
+    logger.add(lambda msg: None, format=format_, catch=False, colorize=colorize)
+    with pytest.raises(ValueError, match=r"Failed to format log record: key 'missing' not found."):
+        logger.opt(colors=colors).info("Hello")

tests/test_patch.py

@@ -83,3 +83,13 @@ def patch_3(record):
     logger.patch(patch_1).patch(patch_2).patch(patch_3).info("Test")
 
     assert writer.read() == "12 Test\n"
+
+
+def test_patcher_added_keys_work_in_format(writer):
+    def patcher(record):
+        record["my_value"] = 42
+
+    logger.add(writer, format="{message} | {my_value}")
+    logger.configure(patcher=patcher)
+    logger.info("Hello")
+    assert "Hello | 42" in writer.read()