PyLint message: logging-format-interpolation

Question

For the following code:

logger.debug('message: {}'.format('test'))

pylint produces the following warning:

logging-format-interpolation (W1202):

Use % formatting in logging functions and pass the % parameters as arguments Used when a logging statement has a call form of “logging.(format_string.format(format_args...))”. Such calls should use % formatting instead, but leave interpolation to the logging function by passing the parameters as arguments.

I know I can turn off this warning, but I'd like to understand it. I assumed using format() is the preferred way to print out statements in Python 3. Why is this not true for logger statements?

Answer 1

It is not true for logger statement because it relies on former "%" format like string to provide lazy interpolation of this string using extra arguments given to the logger call. For instance instead of doing:

logger.error('oops caused by %s' % exc)

you should do

logger.error('oops caused by %s', exc)

so the string will only be interpolated if the message is actually emitted.

You can't benefit of this functionality when using .format().

---

Per the Optimization section of the logging docs:

Formatting of message arguments is deferred until it cannot be avoided. However, computing the arguments passed to the logging method can also be expensive, and you may want to avoid doing it if the logger will just throw away your event.

Answer 2

Maybe this time differences can help you.

Following description is not the answer for your question, but it can help people.

If you want to use fstrings (Literal String Interpolation) for logging, then you can disable it from .pylintrc file with disable=logging-fstring-interpolation, see: related issue and comment.

Also you can disable logging-format-interpolation.

---

For pylint 2.4:

There are 3 options for logging style in the .pylintrc file: old, new, fstr

fstr option added in 2.4 and removed in 2.5

Description from .pylintrc file (v2.4):

[LOGGING]

# Format style used to check logging format string. `old` means using %
# formatting, `new` is for `{}` formatting,and `fstr` is for f-strings.
logging-format-style=old

for old (logging-format-style=old):

foo = "bar"
self.logger.info("foo: %s", foo)

for new (logging-format-style=new):

foo = "bar"
self.logger.info("foo: {}", foo)
# OR
self.logger.info("foo: {foo}", foo=foo)

Note: you can not use .format() even if you select new option.

pylint still gives the same warning for this code:

self.logger.info("foo: {}".format(foo))  # W1202
# OR
self.logger.info("foo: {foo}".format(foo=foo))  # W1202

for fstr (logging-format-style=fstr):

foo = "bar"
self.logger.info(f"foo: {foo}")

Personally, I prefer fstr option because of PEP-0498.

Answer 3

In my experience a more compelling reason than optimization (for most use cases) for the lazy interpolation is that it plays nicely with log aggregators like Sentry.

Consider a 'user logged in' log message. If you interpolate the user into the format string, you have as many distinct log messages as there are users. If you use lazy interpolation like this, the log aggregator can more reasonably interpret this as the same log message with a bunch of different instances.

Answer 4

Here is an example of why it's better to use %s instead of f-strings in logging.

>>> import logging
>>> logging.basicConfig(level=logging.INFO)
>>> logger = logging.getLogger('MyLogger')
>>>
>>> class MyClass:
...     def __init__(self, name: str) -> None:
...         self._name = name
...     def __str__(self) -> str:
...         print('GENERATING STRING')
...         return self._name
...
>>> c = MyClass('foo')
>>> logger.debug('Created: %s', c)
>>> logger.debug(f'Created: {c}')
GENERATING STRING

Inspired by Python 3.7 logging: f-strings vs %.

Answer 5

format is indeed the preferred new style.

You should however not call format() directly, instead letting the interpolation of messages in logging do its job.

You can use the following code to enable using format style with lazy interpolation in python 3.2+

import logging

class BracketStyleRecord(logging.LogRecord):
    def getMessage(self):
        msg = str(self.msg) # see logging cookbook
        if self.args:
            try:
                msg = msg % self.args # retro-compability for 3rd party code
            except TypeError: # not all arguments converted during formatting
                msg = msg.format(*self.args)
        return msg

logging.setLogRecordFactory(BracketStyleRecord)
logging.basicConfig()
logging.error("The first number is %s", 1) # old-style
logging.error("The first number is {}", 1) # new-style

For details, caveats and references see this answer.

Answer 6

maybe for someone the solution is disabling in settings.json in Visual Studio Code

 "python.linting.pylintArgs": [
    "--disable=C0111,C0114,C0115,C0116б,W1203",
    "--disable=missing-module-docstring",
    "--disable=missing-class-docstring",
    "--disable=missing-function-docstring",        
]

Answer 7

Might be several years after but having to deal with this the other day, I made simple; just formatted the string before logger.

message = 'message: {}'.format('test')
logger.debug(message)

That way there was no need to change any of the settings from log, if later on desire to change to a normal print there is no need to change the formatting or code.

Answer 8

"logging-format-interpolation (W1202)" is another one wrong recommendation from pylint (like many from pep8). F-string are described as slow vs %, but have you checked ? With 500_000 rotation of logging with f-string vs % -> f-string:23.01 sec. , %:25.43 sec.

So logging with f-string is faster than %. When you look at the logging source code : log.error() -> self.logger._log() -> self.makeRecord() -> self._logRecordFactory() -> class LogRecord() -> home made equivalent to format()

code :

import logging
import random
import time

loops = 500_000
r_fstr = 0.0
r_format = 0.0

def test_fstr():
    global loops, r_fstr
    for i in range(0, loops):
        r1 = time.time()
        logging.error(f'test {random.randint(0, 1000)}')
        r2 = time.time()
        r_fstr += r2 - r1

def test_format():
    global loops, r_format
    for i in range(0 ,loops):
        r1 = time.time()
        logging.error('test %d', random.randint(0, 1000))
        r2 = time.time()
        r_format += r2 - r1

test_fstr()
test_format()
print(f'Logging f-string:{round(r_fstr,2)} sec. , %:{round(r_format,2)} sec.')