InterceptLogger example will double-format logs when adding kwargs

[iFreilicht]

The example for the InterceptLogger has a small issue when a library formats a string into something containing curly braces and you add a keyword argument to the logging call.

To demonstrate, I made these this change to test_interception.py:

-        logger.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())
+        logger.opt(depth=depth, exception=record.exc_info).log(
+            level, record.getMessage(), logger_name=record.name
+        )

Which is something we did in our codebase.

And added this test

def test_no_double_logging(writer):
    with make_logging_logger(None, InterceptHandler()) as logging_logger:
        logger.add(writer, format="{message}")
        logging_logger.info("Literally %r", "s_{not} {formatted}")

    result = writer.read()
    assert result == "Literally 's_{not} {formatted}'\n"

to demonstrate the issue it caused. The test fails with a KeyError. To be clear, this test will pass without the change to the InterceptLogger above, because formatting is only triggered when args or kwargs are passed, see here:

loguru/loguru/_logger.py

Lines 2139 to 2141 in 0a0985b

	elif args or kwargs:
	colored_message = None
	log_record["message"] = message.format(*args, **kwargs)

Alternatively, to repro the issue, you can use this patch, which also contains the fix:

+        # Prevent unintentional and likely unsuccessful formatting
+        message = record.getMessage().replace("{", "{{").replace("}", "}}")
         logger.opt(depth=depth, exception=record.exc_info).log(
-            level, record.getMessage(), logger_name=record.name
+            level, message, logger_name=record.name
         )

I originally wanted to submit a PR for this, but I'm hesitant because the actual current code (as shown in the example) works, so it doesn't really need to be fixed. The bug is only triggered when one tries to extend it, and even in that case, it happens only when a library originally used curly braces in its formatted messages. In my case, this got triggered when running parse with the DEBUG logging level.

So, what am I to do? Should I submit a PR that changes the example in the README and the test? Or is this basically a non-issue? I did consider potential security implications of this, because user-generated input can make it into the message, which can cause information leaks when the result is returned to the user, but I haven't looked into actually creating a PoC, and for that to actually be harmful you'd need to return your logs to the user, which is probably a bad idea anyway.

[Delgan]

Hey @iFreilicht. Thank you for sharing these details.

Indeed, the problem is that when there are additional arguments such as your logger_name, the log() function will try to format them within the message. But since you do not control the base message, this can cause unexpected errors. This is a problem quite similar to : Why logging a message with f-string sometimes raises an exception?

We could escape the braces present in the message as you suggested, but that would only be relevant when additional arguments (such as logger_name) are provided to the log() method. For the default case, since not everyone needs logger_name to appear in the "extra" dict, it would cause undesirable brace duplication.

I'm wondering, though: do you actually need the logger_name to be passed as a formatting argument? Could you maybe use bind() instead, which would allow you to save the logger_name as an attribute of the extra dict without it interfering with formatting?

For example:

class InterceptHandler(logging.Handler):
    def emit(self, record):
        # Get corresponding Loguru level if it exists.
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno

        # Find caller from where originated the logged message.
        frame, depth = inspect.currentframe(), 0
        while frame:
            filename = frame.f_code.co_filename
            is_logging = filename == logging.__file__
            is_frozen = "importlib" in filename and "_bootstrap" in filename
            if depth > 0 and not (is_logging or is_frozen):
                break
            frame = frame.f_back
            depth += 1

        logger.bind(logger_name=record.name).opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )