[HN Gopher] Flake8-Logging
___________________________________________________________________
Flake8-Logging
Author : zdw
Score : 64 points
Date : 2023-09-10 02:22 UTC (1 days ago)
(HTM) web link (adamj.eu)
(TXT) w3m dump (adamj.eu)
| EdwardDiego wrote:
| Nice! I'll try this in our project tomorrow, I suspect it'll be
| bad.
| sirlantis wrote:
| Related ruff rule: https://beta.ruff.rs/docs/rules/logging-f-
| string/
| nbadg wrote:
| Also, ruff has an issue to implement all of the rules. OP,
| excellent idea, and also, hats off to the ruff team, really:
| https://github.com/astral-sh/ruff/issues/7248
| drcongo wrote:
| Loved the little message to Charlie Marsh at the end of the OP.
| misnome wrote:
| I've given up trying to push against f-strings/format in log
| messages; I even wrote a bowler/fissix fixer to automatically
| transform our codebase from them/.format/%-format into the
| delayed form.
|
| But nobody ever used it, and nobody changed the way they wrote
| them.
|
| Admittedly it is convenient and usually reads better; I just gave
| up, even for my own code; if any become performance issues we can
| pick it up on profiling.
| touristtam wrote:
| Isn't the argument about lazy loading?
| sirlantis wrote:
| A more obscure one is about handling the exception when
| __str__ or __repr__ raises.
| ochoseis wrote:
| If your code has a lot of debug and info statements, but you
| only set production to the warn level, then you're wasting
| cycles interpolating strings that go nowhere.
| mikepurvis wrote:
| Surely string interpolation is cheap, especially given that
| we're talking about Python here?
|
| I'd be more worried about cases where you're calling some
| function to produce a novel value that will then be
| included in the log string-- and Python doesn't have lazy
| argument evaluation so you'll pay the cost of that function
| call regardless.
| RandomBK wrote:
| If it's CPython we're talking about, a _function call_
| can cause non-negligence performance impact in a hot
| loop. I wouldn 't assume anything in Python is 'cheap'
| kolanos wrote:
| This just makes me wish fstrings had a lazy interpolation
| mode.
| kstrauser wrote:
| I'd be curious to see that benchmark. I also don't have an
| initial guess about which would be faster:
|
| * Format a string, pass it to a function, and the function
| decides whether to emit it, then how to render it.
|
| * Pass in the template and parameters to a function, and
| the function decides whether to emit it, then how to render
| it.
|
| F-strings are pretty darn fast. I don't know how much
| relative overhead there would be in calling the logging
| function, and in the logging function's decision tree about
| whether to emit a log message.
| Veserv wrote:
| Well, the actual solution is that your log should not
| contain any formatted statements at all. Formatting
| should be done offline as a post-processing step when
| viewing/ingesting the log, not when producing the log.
|
| While it might not be too visible in Python, formatting
| is a very significant cost. I work with systems that can
| output tens to hundreds of millions of log lines per
| second per core with the limiting factor being memory
| bandwidth. It would be pretty challenging in many systems
| to get even a tenth that rate. I can literally add 10,000
| logs per second per core at a 0.1% system overhead. Pre-
| formatting your logs is convenient when just starting
| out, but you should really switch to a more efficient
| logging system pretty quickly.
| kstrauser wrote:
| That's a use case I've never considered for Python's
| logging module. Is that emitting a message for every
| iteration of an inner loop? It seems like your log
| analyzer would curse your name unto 3 generations for
| making it deal with that.
| Veserv wrote:
| Auto-instrumenting every function call is the more common
| use case demanding those data rates. I mostly work in C,
| so the costs of doing that are in the 10-40% overhead
| range. In Python the overhead is in the single digit
| percent range. You deal with it by having good graphical
| log viewing tools.
|
| Really, your problem is actually getting the logs off the
| system. When you generate logs at 15 GB/s per core the
| only device fast enough is RAM. If you want any logs
| larger than a circular RAM disk you need to deliberately
| slow down your logging rate so your ethernet can keep up.
| ochoseis wrote:
| Something I have found to work well in Python is static
| log messages with details in the `extras` kwarg
| (especially if you're formatting logs as json).
| nbadg wrote:
| Setting aside the performance argument, strictly adhering to
| this rule makes a big difference in 3rd-party tools like
| Sentry. If you pre-format log messages, the parameters don't
| get captured, and (at least in my experience) it sometimes
| shows up as a separate event entirely.
|
| Having written a monkeypatch for the stdlib logging library at
| Hipmunk (RIP) for our GDPR effort, I can say: I have a lot of
| thoughts about ``logging``, and few of them are good. But it's
| definitely better than print statements!
| paulddraper wrote:
| Scala has a very useful feature: pass-by-name.
|
| It implicitly constructs a lambda for the argument.
| theamk wrote:
| 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.
| globular-toast wrote:
| Is that really any different from any other type error you
| might miss? Just run your tests with logging in info mode.
| dboreham wrote:
| Which misses the bug that only shows up when logging is at
| error or warn level.
| Veserv wrote:
| 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 wrote:
| > 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/stabl
| e/api.html#structlog.stdli...
| teddyh wrote:
| > _LOG005 use exception() within an exception handler_
|
| In Python, exception handling is part of the normal control flow.
| Therefore, when an exception happens, it is not always the case
| that you want to log a full stack trace. try:
| thing = things[0] except IndexError: log.error("Not
| enough things!") return
|
| I think that even _recommending_ a log.exception() here would
| actually be a bad thing.
___________________________________________________________________
(page generated 2023-09-11 22:00 UTC)