A few days back, I was implementing a feature, and when I was done and happy with my work, I decided to commit the code. We have enabled pre-commit hooks in our repository to maintain some coding formats and reduce the burden on the folks reviewing the code. One of the code checkers that run as part of the pre-commit check is Pylint. Pylint gave me the warning 'logging-fstring-interpolation (W1203)' and the pre-commit check kept failing. Even though I knew what needed to be done to fix the warning, being me, I could not just leave it be. I wanted to know the why part of it.
Other Pylint warnings related to the logging module are:
Pylint
A little introduction about pylint. Pylint is a static code analyzer, it analyses your code without actually running it. Pylint looks for potential errors, gives suggestions on coding standards that your code is not adhering to, potential places where refactoring might help, and also warnings about smelly code.
Sometimes there are false positives, but you can inspect and decide for yourself whether it flagged the line incorrectly or not. If you identify it as a false positive, you can disable the pylint check for that particular line.
Overall, I think it takes out a lot of pain from the reviewer to point out code smells and enforce coding standards. I would say this module has saved hours of review time.
logging-fstring-interpolation warning
Python has multiple ways of string interpolation. I have explained the details of it in a previous blog - String Interpolation in Python
Even though we are using the latest string interpolation mechanism in python, the Pylint checker is giving us a warning that there is something wrong. The official documentation for this warning says:
Use another type of string formatting instead. You can use % formatting but leave interpolation to the logging function by passing the parameters as arguments.
To understand what was happening behind the hood, I wrote this code.
Here, I have an Employee class with an __str__ magic method. The logging module is configured to log into the console and the logging level is set to DEBUG. The statements of interest are all debug statements, and I also added some headings to understand what section we are executing now.
Running this code with the logging level set to DEBUG. I expect to see the str method called for all the cases because the log level is DEBUG is the lowest and all the log messages will be printed.
The response is as expected. The string evaluation of the object takes place and then the log statement is evaluated.
What if the log level is set to INFO, but the log statements are at the DEBUG level?
I expect the string evaluation to be deferred until the logger determines whether this log statement is above the log level set, i.e., all the statements with log level as INFO and higher will be printed whereas all the statements with log level as DEBUG will be ignored. If the log statements with DEBUG are ignored, then there is no need to call the str method of the objects.
Making only 1 change on line #5, I executed the code.
The response was not something I was expecting.
Upon inspection, it was clear the evaluation of the message objects was happening irrespective of whether the statement was executed or discarded.
So irrespective of what type of string interpolation I use, the order of events is as follows:
evaluate all the arguments to the log.debug() - this calls the str method,
Call the log.debug(),
Determine whether to log it or discard it.
This seemed very counterintuitive because then the logging statement when turned off will still consume time and memory. I decided to peek into the logging library. Looking at the function signature it was clear, there is nothing wrong with the library. But I am not using the library in the intended way.
The intended way to use the logger function is to pass the string template as the first argument and the arguments to be substituted as *args. This way, the string interpolation happens within the logger library and not when I call the logger method.
The correct way to invoke the logging statement where the string interpolation is deferred until it is necessary.
Added two more lines of code and repeated the experiment. In this case, I am passing the %-formatted string template separately and the argument to substitute it with separately.
Running this code again, the result is as expected, the string evaluation is not happening because the log level is set to INFO.
After changing the log level to debug on line #5, the log statement is getting printed as expected.
So, the order of events will be:
Call the log.debug(),
Determine whether to log it or discard it.
Discards the log because the log level is below the level set.
Evaluate the message object by substituting the arguments.
Now that the internal workings and the correct usage is clear, let us understand the impact of this small change on our program.
Impact
You might think this string interpolation is harmless, but if the logging statement is in a function that is called frequently and the logging level is set to be discarded during normal operation, you are wasting away a lot of execution cycles. To understand the impact, I looped the logging statements 100,000 times, collected the run time, and tabulated it.
The x-axis defines different approaches and the y-axis gives the time in milliseconds for each approach.
When we are logging and the log message evaluation is expensive, using the approach of deferred evaluation can save a lot of time. When you want to turn off the debug logs and run in optimized mode. Otherwise, all the approaches are yielding similar run time.
Conclusion
Hope this blog helps someone who is scratching their head trying to figure out why the Pylint-type checker is giving this weird warning. Pylint is trying to tell you to check your syntax because you could be committing a mistake by not using deferred evaluation. This warning message is generated when you are trying to use f-string substitution in the logging statement.
Instead of simply disabling the warning, now you know the reason behind it and how to handle it the correct way.
Share with me your thoughts on this in the comments! Or leave a like if you learned something new.
