[FIXED] Python logging.Formatter uses "%"-formatting instead of "{" even when "{" specified

Issue

I tried to create a custom logger with a custom formatter, inheriting them from logging.Logger and logging.Formatter accordingly. However, even though I specified style to be "{", I get an error. As far as I understood, this error is caused by the fact, that formatter tries to format using old-style % formatting.

Here's example of my logger.py, formatter.py and main.py to reproduce this.

# logger.py
import logging

from formatter import CustomFormatter

class CustomLogger(logging.Logger):
    def __init__(self, name: 'str'):
        super().__init__(name)
        self._console_handler = logging.StreamHandler()

        format_string_for_console = '[{levelname}] {name}: {message}'
        time_format_string = '%Y-%m-%d %H:%M:%S%Z'

        console_formatter = CustomFormatter(
            fmt=format_string_for_console,
            datefmt=time_format_string,
            style='{')

        self._console_handler.setFormatter(console_formatter)

# formatter.py
import copy
import logging

class CustomFormatter(logging.Formatter):
    def __init__(self, fmt: 'str' = None, datefmt: 'str' = None, style: 'str' = '%'):
        self.__format = f'Some modification to default format {fmt}'
        self.__date_format = datefmt
        self.__style = style
        super().__init__(fmt, datefmt, style)

    def format(self, record: 'logging.LogRecord') -> str:
        record_copy = copy.copy(record)
        return logging.Formatter(
            fmt=self.__format,
            datefmt=self.__date_format,
            style=self.__style
        ).format(record_copy)

# main.py
from logger import CustomLogger as CL

logger = CL('test_logger')
logger.warning('info_msg {}', 1)

Don't tell me about ridiculousness of this MVP, it's extremely minified to be as little as possible, but still reproduce an error. The error I get with this has this stacktrace:

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/__init__.py", line 1085, in emit
    msg = self.format(record)
  File "/usr/lib/python3.8/logging/__init__.py", line 929, in format
    return fmt.format(record)
  File "/usr/lib/python3.8/logging/__init__.py", line 668, in format
    record.message = record.getMessage()
  File "/usr/lib/python3.8/logging/__init__.py", line 373, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "<stdin>", line 1, in <module>
Message: 'info_msg {}'
Arguments: (1,)

I must be doing something wrong, but I can't get what. Any help would be appreciated.

Solution

There are two levels of formatting:

1. Formatting the message and arguments passed in a logging call. These are always formatted using %, for backward compatibility - logging predates the other kinds of formatting.
2. Formatting the message generated by the previous step together with other things such as the time of the event, process ID, thread ID, current function, current module and any other contextual information passed to the logging call. This level can use the style passed to a formatter to decide how to format the message. In this higher level of formatting, the message in the format string of the formatter will hold the value determined in the previous step.

Answered By - Vinay Sajip