Pylint Logging Format Interpolation

This article explains why fstring interpolation is bad in logging functions and why you should rather use:

logging.info("Your string %s", my_var)

instead of:

logging.info(f"Your string {my_var}")

or:

logging.info("Your string %s" % my_var)

Context

In python you can have code using logging functions for better observability. For instance:

"""
Demonstration module for logging fstring
interpolation pylint error.
"""

import logging

logging.basicConfig(level="INFO")
logger = logging.getLogger(__name__)


def main() -> None:
    """
    Main method. Nothing fancy about it.
    """
    try:
        print(8 / 0)
    except ZeroDivisionError as exc:
        logger.info(f"The division failed: {exc}")


if __name__ == "__main__":
    main()

Running the above code will raise the following error:

zsh> poetry run python main.py
INFO:__main__:The division failed: division by zero

So far so good.

Error: Use lazy % formatting in logging functions

The next step is to push our code into production, hence, applying black, mypy and pylint formatting over your code.

Note: you can encompass all of the above within a similar Makefile, see hereafter.

black:
    poetry run black main.py

mypy:
    poetry run mypy main.py

pylint:
    poetry run pylint main.py

checks: black mypy pylint

zsh> make checks
main.py:19:8: W1203: Use lazy % formatting in logging functions (logging-fstring-interpolation)

------------------------------------------------------------------
Your code has been rated at 9.00/10

So what’s happening here?

You can see that pylint complains about us using a Python fstring in the logging function.

The error message hints us to use the lazy % formatting instead.

Because we want to comply with its instruction, we edit our code, changing the line by the following:

logger.info("The division failed: %s" % exc)

Confident, we run our code again, switching for a lazy % formatting and expecting a 10/10 rating:

zsh> make checks
main.py:19:8: W1201: Use lazy % formatting in logging functions (logging-not-lazy)
main.py:19:20: C0209: Formatting a regular string which could be an f-string (consider-using-f-string)

------------------------------------------------------------------
Your code has been rated at 8.00/10 (previous run: 9.00/10, -1.00)

Surprise! Pylint seems not to like either fstring or lazy % formatting…

It even comes up with a new error into place!

We could obviously silent the error, adding the following inline comment:

logger.info(  # pylint: disable=logging-fstring-interpolation
    f"The division failed: {exc}"
)

Which would gives us a nice and neat 10/10 rating:

zsh> make checks
-------------------------------------------------------------------
Your code has been rated at 10.00/10 (previous run: 9.00/10, +1.00)

However, better than hiding the dirt under the rug, it is better to understand why pylint is raising this error.

So, why fstring interpolation is bad in logging functions?

Hidden Motivation: Performances!

The problem is not so much about us using fstrings in place of lazy % formatting.

The problem lies about performances.

Jumping back into our code example, what fixes it – without us having to cheat around by muting the error – is a lazy % formatting with a comma:

logger.info("The division failed: %s", exc)

The Devil is in the details!

The motivation behind the warning is around performance.

With this final version of our code, if a log statement is not emitted, then the interpolation cost is saved.

The solution was to shift from:

logger.info("The division failed: %s" % exc)

to:

logger.info("The division failed: %s", exc)

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