logging-format-interpolation for f-strings

[eddie-dunn]

Pylint will warn against using .format and % when logging. As the example below shows, I think it would be prudent to also output warnings when using f-strings.

Steps to reproduce

"""Docstring"""
import logging


def main():
    """Main"""
    url = 'http://example.com/%fe'
    # This works:
    logging.error(
        'url is %s | log method: %s', url, 'logging with parameters only')

    # This will crash the logger, but pylint will output
    # logging-format-interpolation:
    logging.error(
        'url is {} | log method: %s'.format(url), 'logging with .format')

    # This will also crash the logger, but pylint accepts it:
    logging.error(f'url is {url} | log method: %s', 'logging with f-string')


main()

Current behavior

Pylint does not warn against f-string interpolation in loggers.

Expected behavior

Pylint should warn against f-string interpolation in loggers, just as it warns against .format-interpolation.

pylint --version output

pylint 1.8.1, 
astroid 1.6.0
Python 3.6.2 (default, Sep 22 2017, 12:45:49) 
[GCC 6.3.0 20170516]

[PCManticore]

Thanks!

[sscherfke]

Please not! f-Strings are more readable and fast. We don't want to mix old-style and new-style formatting in our code (this is IMHO worse than not using logger.info('hello %s', name).

[sscherfke]

@PCManticore Or give it at least a different error message (e.g., logging-fstring-interpolation) so that this can be ignored (but not .format()) and users can keep using f-Strings.

[PCManticore]

A different message sounds good to me, if you can please create an issue with it, that would be great! Nevertheless, f-strings might be fast, but there's no need to compute them if there is no need to emit the logging message if its under the expected logging level.

[eddie-dunn]

@sscherfke as @PCManticore hinted at, the reason that pylint emits the logging-format-interpolation warning is because it is inefficient to compute the string for a log message that won't be logged. This also applies to f-strings, since even if they are faster than .format it is still slower to interpolate than not interpolate at all.

I share your opinion on the greatness of f-strings, but if you are using them with the logging module, you are using the logging module incorrectly/inefficiently.

[sscherfke]

Sometimes I just don care. Practicality beats purity. 😉

[zachliu]

I agree with @sscherfke. Code readability out weights the tiny efficiency increase.

[leahein]

Seconded. IMO mixing old-style formatting and f-strings throughout the application is less desirable than the cost of computing the string interpolation.

[PCManticore]

Commenting on this issue won't change anything, if you don't agree with the warning, feel free to disable it, but this is going to be the default in pylint.

[Steffan-Ennis]

Python not being my first nor preferred language. It does make it harder to quickly read and understand code.

I agree with the above sentiments. I thought the goal of linters was to make code consistent and easier to parse.

[pzelnip]

Please see the timing results at #2395 Those findings indicate that the difference in performance when logging messages are suppressed is minimal at best (~1%), and if logging statements are emitted then f-strings are actually more performant (though again, the performance difference is so small that it's not worth preferring either for performance reasons).

[joshburkart]

Yeah, this warning seems like hardcore premature optimization.

Commenting on this issue won't change anything, if you don't agree with the warning, feel free to disable it, but this is going to be the default in pylint.

These kinds of decisions for defaults should be made by consensus rather than by fiat. Also, the imperious tone is not appreciated.

[FrankDMartinez]

How about an option to exempt f-strings? By default, they would be flagged; with this option on, no.

[cra]

You know what's even faster? Not logging at all and not writing any messages.

How about an option on pylint prudent behaviour for any stdout output?

[theY4Kman]

There's one reason I drop down from f-strings to regular modulus interpolation:

queryset = MyModel.objects.relevant()
logger.debug('About to do the dirty to: %s', queryset)

If that queryset is evaluated when log level = INFO, we're talking far more than a 1% performance difference.

[uriva]

The benefits of using f-strings in logs are proven - enhanced readability and less writing effort.

The downsides are highly speculative; only come into play if logging does not really occur && the f-string contains costly operations.

Controversial coding style practices should not be addressed in such a common dev tool.
("Controversial" being a huge understatement here to judge by the comments and votes)

primum non nocere

[eddie-dunn]

Just commenting to add that I have no particular bone in this game, save that I value consistency over 'practicality'.

Also, if people had actually read the original bug report, you'd have noticed that my main gripe is that Pylint doesn't warn against attempting logging strings that will crash the logger in the case of f-strings, which can happen when you inadvertently mix different string interpolation methods.

url = 'http://example.com/%fe'
# This will crash the logger, but pylint will output logging-format-interpolation:
logging.error('url is {} | log method: %s'.format(url), 'logging with .format')

# This will also crash the logger, but pylint accepts it:
logging.error(f'url is {url} | log method: %s', 'logging with f-string')

Sure, it's an edge case, and that pylint warns against the first logging attempt is a lucky side effect of how the logging-format-interpolation warning works, but that warning still would prevent people from writing code that leads to runtime crashes, which I think is fairly practical.

In other words I see no problem with allowing logging.error(f'the url is {url}') (if @PCManticore agrees with the sentiment expressed here). I do think that logging.error(f'{url} %s', 'some string') (i.e., mixed interpolation) should produce a warning since it may lead to runtime crashes.

[chdsbd]

It seems like everyone here is talking about performance. There are other benefits to letting logging do the interpolation.

1. if interpolation fails, it will be logged instead of raising an exception
2. things like Sentry can aggregate log messages. If you interpolate before logging, Sentry would see it as one event 0

[sscherfke]

This all has nothing to do with pylint.

If each kind of interpolation raises a different pylint warning, users can customize pylint to match their world-view on logging. The discussion which one is the best can be conducted elsewhere. ;-)

[kootenpv]

@sscherfke I think the discussion is ultimately what should be the default for pylint.

[lazarillo]

There's one reason I drop down from f-strings to regular modulus interpolation:

queryset = MyModel.objects.relevant()
logger.debug('About to do the dirty to: %s', queryset)

If that queryset is evaluated when log level = INFO, we're talking far more than a 1% performance difference.

Can you explain what you mean, @theY4Kman ?

It seems to me that you are calculating queryset anyway. Are you saying there is some sort of lazy evaluation happening here? What is MyModel that it has guaranteed lazy eval? And why would modulus leave it lazy whereas f-string forces the eval?

Thanks!

[Pierre-Sassoulas]

The configuration for fstring is avaialble since pylint 2.4 and was introduced in eeca6cf.

See, http://pylint.pycqa.org/en/latest/whatsnew/2.4.html?highlight=fstring%20interpolation

Allow the option of f-strings as a valid logging string formatting method.

logging-fstring--interpolation has been merged into logging-format-interpolation to allow the logging-format-style option to control which logging string format style is valid. To allow this, a new fstr value is valid for the logging-format-style option.

I'm going to lock to prevent further discussions here.