5 ms·

I believe that "LOG011 avoid pre-formatting log messages" is a terrible rule, and I always push for the opposite in all the codebases we work on: always pre-for

by theamk 3y ago

I believe that "LOG011 avoid pre-formatting log messages" is a terrible rule, and I always push for the opposite in all the codebases we work on: always pre-format all messages. The reason is simple: logging module made a weird decision to ignore all the formatting errors, which means that a lot of testing generally fails to find any logging problems.. Put "logger.info("Queue size: %d", 'hello')" int your source and it'll pass all the unit tests, all the system tests, and would only be detected in prod, at the worst possible time when the system is failing and someone really needs to know the queue size. It is much better to preformat the messages, so tests and IDEs catch it later. And yes, there are some rare logging statement in the tight loop - and in this rare case you can add explicit "if logger.isEnabledFor(logger.DEBUG):" call.. This is annoying, but it should be pretty rare, you should normally avoid logging code in tight loops.

Veserv 3y ago
Your argument is that logging modules do not do proper type-checking on their format parameters, therefore you should pre-format all messages since pre-formatting forces the compiler/runtime to do the type-checks. Why not just solve the problem directly by just get a better logging module that does the checks? We already established the compiler/runtime can do the checks, it is just a question of getting the checks to run. Also, frankly, a proper logging system implemented in C should be able to support tens of millions of logging statements per second per core. There is little reason to be stingy on logging even in optimized C let alone a language as slow as Python. A system where manually inserted logging statements constitute a material overhead almost certainly means your logging system should be improved.
- Spivak 3y ago
  > directly by just get a better logging module that does the checks Because logging is a cross-cutting concern and the built-in logging module is the common denominator that packages in the Python ecosystem have to generate logs without knowing anything about the application they might be embedded into. So while you're free to use whatever logging module in your own top-level code, your dependencies will use the logging module and you have to deal with that. Packages have to find a way to integrate with it https://www.structlog.org/en/stable/api.html#structlog.stdlib.recreate_defaults https://www.structlog.org/en/stable/api.html#structlog.stdli...
globular-toast 3y ago
Is that really any different from any other type error you might miss? Just run your tests with logging in info mode.
- dboreham 3y ago
  Which misses the bug that only shows up when logging is at error or warn level.
- theamk 3y ago
  logging's formatter ignores errors. It will complain on console, but no exception will be raised, so the tests would pass. Unless you open test logs and manually examine output (and who does this for passing tests?), the test results will show green.
  - mixmastamyk 3y ago
    Not exactly, it does not ignore errors. First, an error doesn’t occur until a format op at/above level happens. Change to log.error() for example and watch the fireworks. Second, true it will continue on, but the error is well logged with a traceback. The thinking, I happen to agree with is that a logging error shouldn’t halt the program. A logging error doesn’t cause an error in the program itself. I could see an argument the other way in specific situations however. I’d probably subclass Logger instead if that is not configurable.
    - msm_ 3y ago
      >Second, true it will continue on, but the error is well logged with a traceback. The thinking, I happen to agree with is that a logging error shouldn’t halt the program. And the parameters are also logged, so you don't really lose anything should this somehow happen in production.
mixmastamyk 3y ago
Better strategy I think is to disallow %d and others, which is never necessary in logs. Have always used either %s or %r without issue. Linters will tell you if you have the wrong number of params and you’ll get a big exception at runtime as well. Better to avoid unnecessary work, imho.
- theamk 3y ago
  %d is pretry useless, yes. But %.3d is great for time durations where millisecond resolutions are sufficient. Or %_d (group digits) for large numbers like filesizes.
  - mixmastamyk 3y ago
    Rereading I see your log level is the true culprit, which is postponing the errors. Not “prod” per se. This problem you mention will continue to be hidden in prod until you drop log level. Preformatting is one way to avoid but feels heavy handed. I always develop at debug level so this never happens. In fact I changed the level default in our dev environment to debug for my own convenience, unrelated to this but prevents it as a side effect.
baq 3y ago
You’ll quickly do a 180 once you feed logs to a monitoring system. In case you’re already doing it, it is the rare occasion that I can unsarcastically say you’re doing it wrong.

by theamk 3y ago

Veserv 3y ago

Your argument is that logging modules do not do proper type-checking on their format parameters, therefore you should pre-format all messages since pre-formatting forces the compiler/runtime to do the type-checks. Why not just solve the problem directly by just get a better logging module that does the checks? We already established the compiler/runtime can do the checks, it is just a question of getting the checks to run. Also, frankly, a proper logging system implemented in C should be able to support tens of millions of logging statements per second per core. There is little reason to be stingy on logging even in optimized C let alone a language as slow as Python. A system where manually inserted logging statements constitute a material overhead almost certainly means your logging system should be improved.

Spivak 3y ago
> directly by just get a better logging module that does the checks Because logging is a cross-cutting concern and the built-in logging module is the common denominator that packages in the Python ecosystem have to generate logs without knowing anything about the application they might be embedded into. So while you're free to use whatever logging module in your own top-level code, your dependencies will use the logging module and you have to deal with that. Packages have to find a way to integrate with it https://www.structlog.org/en/stable/api.html#structlog.stdlib.recreate_defaults https://www.structlog.org/en/stable/api.html#structlog.stdli...

globular-toast 3y ago

Is that really any different from any other type error you might miss? Just run your tests with logging in info mode.

dboreham 3y ago
Which misses the bug that only shows up when logging is at error or warn level.
theamk 3y ago
logging's formatter ignores errors. It will complain on console, but no exception will be raised, so the tests would pass. Unless you open test logs and manually examine output (and who does this for passing tests?), the test results will show green.
- mixmastamyk 3y ago
  Not exactly, it does not ignore errors. First, an error doesn’t occur until a format op at/above level happens. Change to log.error() for example and watch the fireworks. Second, true it will continue on, but the error is well logged with a traceback. The thinking, I happen to agree with is that a logging error shouldn’t halt the program. A logging error doesn’t cause an error in the program itself. I could see an argument the other way in specific situations however. I’d probably subclass Logger instead if that is not configurable.
  - msm_ 3y ago
    >Second, true it will continue on, but the error is well logged with a traceback. The thinking, I happen to agree with is that a logging error shouldn’t halt the program. And the parameters are also logged, so you don't really lose anything should this somehow happen in production.

mixmastamyk 3y ago

Better strategy I think is to disallow %d and others, which is never necessary in logs. Have always used either %s or %r without issue. Linters will tell you if you have the wrong number of params and you’ll get a big exception at runtime as well. Better to avoid unnecessary work, imho.

theamk 3y ago
%d is pretry useless, yes. But %.3d is great for time durations where millisecond resolutions are sufficient. Or %_d (group digits) for large numbers like filesizes.
- mixmastamyk 3y ago
  Rereading I see your log level is the true culprit, which is postponing the errors. Not “prod” per se. This problem you mention will continue to be hidden in prod until you drop log level. Preformatting is one way to avoid but feels heavy handed. I always develop at debug level so this never happens. In fact I changed the level default in our dev environment to debug for my own convenience, unrelated to this but prevents it as a side effect.

baq 3y ago

You’ll quickly do a 180 once you feed logs to a monitoring system. In case you’re already doing it, it is the rare occasion that I can unsarcastically say you’re doing it wrong.