The Python logging module is one of the worst modules in the stdlib. You can see it’s Java inspiration all over it, as being one of the oldest modules it was created before anyone really knew what “pythonic” code was.
Things I really dislike about it is the lack of “context”. Usually log messages are about something - often a request. You can’t attach a request ID or something else a nested set of function calls that log.
The whole library is just really rubbish and has not aged well. There’s no standard way of outputting JSON logs, but there’s a built in way to spawn a socket server that allows the logging configuration to be updated remotely via a bespoke protocol? And everything is built mostly around logging to files.
It also hits that perfect sweet spot of being both overly engineered and totally inflexible. I wanted to funnel our log messages to s3 via the “s3fs” module, which supports a “file like” object that gets written to s3. I had to hack around the various handlers to support this because it assumes it’s a “real” file.
I've been writing Python daily for 15 years but when I have to do any configuration beyond `basicConfig()`, I still groan. In many instances I have wanted to do something like temporarily turn on logging of HTTP requests, which turns into a much more involved effort than it ought to be.
I just recently discovered that there's no documented way to dump the current configuration (https://stackoverflow.com/q/72624883) so you can see what loggers exist and where their output is going.
It's definitely sad that there isn't built-in context support, but if you're looking for a solution to this, it is actually very easy to attach context to logs using threadlocal and a logging filter.
When running a webserver though, an even simpler trick is to add middleware that sets the current request's info as the current thread's name, and then including threadName in your log format.
The contextual support is lacking but it can be done. See this comment from a previous discussion where I briefly described how I’ve used the record factory to help: https://news.ycombinator.com/item?id=31484527
Agreed. One of the most confusing libraries with a ton of magic going on behind the scenes. I also detest PyTest, although not a std lib, pytest is one of the worst in terms of explicitness. It’s very useful but that’s orthogonal. I’ve seen newcomers to python struggle to grasp how pytest just manipulates a billion things behind the scenes.
Overall, I prefer less magic and more explicitness.
I wish I could agree. Every aspect of pytest that I like (fixtures, plugins, etc.) is marred by a boneheaded move to make them autoloaded by default. Loading should be explicit/opt-in. It's dumv that if you pip install something that adds a new pytest plugin it'll automatically modify your runtime behavior. Some of the plugins are great (shoutout to pytest-socket), but it has the same issue flake8 has with the plugin ecosystem where the quality varies wildly.
I might be in the minority but I also find python's mock implementation awful. Mockito in Java is way better where you explicitly state which calls you expect and if you get an unexpected call it errors out.
The implicit magic makes writing pytest tests painless.
Also with improvement of type hinting, tooling like PyCharm starts to understand pytest better and make it easier to read and manage and a lot of the magic can be dispellt by written out explicitly. Though this need some discipline from the dev team.
PSL unittest is very explicit and has no magic. Ironically it also has Java written all over it. You must be the first person I met who prefer unittest to pytest.
camelCase is idiomatic in Smalltalk, which as a language and a community was a pretty big influence on other dynamic OO languages like Python and Ruby, and from whence SUnit comes, and thus the whole xUnit world, derives.
So, it's maybe not the best evidence that the Python version is particularly a clone of the Java port.
Pytest is very opinionated about how and when it's going to be run. If you want to put a test in say, Jupyter or a Markdown block, unittest is much more amenable to just doing what you want without having to read through documentation to break a whole bunch of magic behavior.
What do you mean? Pytest rules! Yes there is some magic, but if you let it take control, it is very convenient to write and run tests with it. Just... you need to trust it and it will do its job.
Strong agree on all points! The number of times I had to debug into the pytest source code because developers (the ones using pytest) thought it would be cool to use some decorator black magic to manipulate global state behind the scenes which pytest not just makes very easy but actually encourages and which was obviously going to break sooner or later…
And regarding the sibling comment: Yes, I prefer unittest as well.
>> You can see it’s Java inspiration all over it, as being one of the oldest modules it was created before anyone really knew what “pythonic” code was.
The irony is Java logging moved on and with newer libraries offers better supports for lazy evaluation, structured logging and multiple output formats, while Python logging seems stuck with an ancient copy of log4j 1.x
> there’s a built in way to spawn a socket server that allows the logging configuration to be updated remotely via a bespoke protocol
That sounds like there's a Log4shell-like vulnerability waiting to be found. But I couldn't even find it, I found the SocketHandler but that's just a log destination.
A few months ago I built a project and wanted to add logging. After searching around, I ended up selecting loguru and it definitely is a nicer user experience. But I also didn't really love it, for reasons that I don't recall now. I would look to it again, simply for lack of a better choice.
Sadly, my social media is subscribed to by pretty heavy hitters in the Python community, but when I asked about the best logging for python it was all crickets. Maybe that says something. :-)
One missing feature of loguru is filter by logging levels. You can still get around it by modifying an internal variable that you can specifically not to
It’s rock solid, at least. I’ve also had the displeasure of working in the logging package. Totally outdated. I created a JSON formatter (also support for context). Huge pain, but always works.
Also logging can be set up remotely, but it's easier to do like that from the container and then configure the hos to send everything to a single log machine.
You should try the loguru library. I was able to roll a rolling-upload-to-s3 adapter in under an hour. Switching to json logs is one bool flag away. Plus it's gorgeous
If you're talking about console.log() and console.error(), I don't think it's trying to be a logging system. The name of that first function is unfortunate but not fooling me.
I can't agree with you more. I switched to Python's logger off of my janky thing about 6 months ago, and I'm hating every second of it. I still have no clue how to turn it on, turn it off, get it to fork output (stdout, stderr, file), nor how to override its behavior.
It's literally easier to just have an IOBuffer laying around.
There are valid complaints in the grandparent, but if you can’t figure out how to fork output to stdout, stderr and file in six months, that’s really on you. You should know how to register multiple handlers if you spent five minutes reading the documentation.
true that. but I've never figured out a good way to do this and have a single test runner module log when invoked directly: python3 test_foo.py and indirectly python3 -m unittest test_foo
The Python logging module is one of the worst modules in the stdlib.
One has to remember that logging was never intended to be some infinitely generalizable metaprotocol for massively streaming parallel notifications to the cloud or whatever. It was meant as a replacement for "if (DEBUG > 4): print(...)". For which I think it does quite well, thank you.
The whole library is just really rubbish and has not aged well. Hate it.
So what have you written that has made people's (not just your bosses' or your clients') lives easier, for nearly 20 years now (if only incrementally)? Do share.
I see and grant your points, but I find this strong emotional rebuke of something that was never intended to be anything more than a simple convenience library to be well, strange.
It clearly is supposed to be more than a convenience library. It’s the blessed, stdlib way to do logging with Python. The module isn’t called “print_with_levels”.
So now everything needs to work with it, it’s internals and it’s way of doing things. And to top it off it’s near impossible to refactor or replace.
One of my favorite features of loguru is the ability to contextualize logging messages using a context manager.
with logger.contextualize(user_name=user_name):
handle_request(...)
Within the context manager, all loguru logging messages include the contextual information. This is especially nice when used in combination with loguru's native JSON formatting support and a JSON-compatible log archiving system.
One downside of loguru is that it doesn't include messages from Python's standard logging system, but it can be integrated as a logging handler for the standard logging system. At the company where I work we've created a helper similar to Datadog's ddtrace-run executable to automatically set up these integrations and log message formatting with loguru
Does loguru come with a lot of global state like the standard logging library? In my experience this makes logging a real PITA when forking multiple processes…
I mentioned this almost every time logging and python come up but one of my favorite feature is logging.exception: https://docs.python.org/3/library/logging.html#logging.Logge.... It allows you to attach the whole exception with stack trace without having to explicitly used “as e” and then use traceback or embed the error in the message. Something like logger.exception(“Failed to connect.”) will print the message and the exception in one go.
I'm using this too, but I always found it very unreadable for people unfamiliar with it. It's so surprising that it catches the exception for you! I end up always adding a commend
```
logger.exception("Failed to connect.") # Will print exception.
```
You can actually do this with any level of log message by passing `exc_info=True` to it. This is super useful in cases where you want to log the exception context, but don't need to be at a high logging level.
The advice I give to people is "think about logging like a feature with customers, just like any other feature." If you think about logging this way, you ideally put yourself in the position of your logs' "customer"- a bleary-eyed teammate who just got paged out of bed at 2am, or a security guy who isn't intimately familiar with your code. Providing extra context for those users is really kind, as they don't have a "secret decoder ring".
Since the article discusses it, I also highly recommend AWS CloudWatch logs. It's super easy to log to CloudWatch from Lambda with the Python logger class. It's a little harder from EC2, but not really that difficult. The advantage is that you don't need to SSH somewhere and navigate to a file and then locate the interesting stuff in that file - You just keep the CloudWatch console open (or keep a link to it handy) and the latest stuff is on top with easy filtering.
Cloudwatch is cheap (even free) for small environments and has very small operational overhead.
The cost, however, can easily get out of hand and AWS does not have per resource billing enabled by default. So it might not be obvious which Log Group is responsible for for which charge.
I also think its console is way inferior than something like Grafana for searching and visualisation.
The console (and its appearance in linked services' 'Logs' tab or similar) is infuriating IMO when your model/what you care about isn't the single instance/invocation that the streams are probably set up as, and you just want all the logs from (all occurrences of, but you're not thinking in those terms) 'thing'.
E.g. a Lambda serving API requests, and you just want 'the logs'.
Other than searching (for something specific) you can only do it (afaik?) with third-party CLI tools, or (found this as I write) v2 (as in, the separate v2 project/binary/distribution methods, not just being up to date :eyeroll:) of the awscli. Short of rearranging your group/stream naming anyway.
Whereas what I really want is just to see all of the logs in the group, with the stream they're from as a filterable property.
(And maybe keep the hyper-specific-ness as a new 'publisher' (what unique thing put the event in the stream) property or something?)
I hear you, and when I did some research on this in the past, going to get logs was the most common reason for engineers to SSH to production hosts.
As a security guy, I hate SSH to production (the whole "cattle, not pets" thing). In my last company we had an internal tool to federate you to the AWS console. We had runbooks in a wiki, and had links literally to the logs for a particular component/service/region - the link would federate you to the right account and take you directly to the target log in cloudwatch logs in the appropriate region. Safer and easier than ssh-to-prod.
> It's super easy to log to CloudWatch from Lambda with the Python logger class
Or even just print(): You've got a unique log group for a lambda, CloudWatch logs autonatically timestamps entries, and stdout & stderr from a lambda both go to the current CloudWatch log stream in the lambda’s CloudWatch logs group.
My experience with Python in Lambda was that my functions ran significantly faster when I used logger rather than print for logging. I agree that Lambda captures stdout to CloudWatch, but my experience was that logger was better (and more intentional).
ed: clarified that this relates to AWS Lambda only
Here’s a logging format that I use and probably you should too. Among other things, it gets around most of the context issues by outputting the file and line number of the code that called the log.
Before I would try and make every log message unique or mostly unique so there weren’t double ups.
I don’t agree with the authors logging clutter though. If you’re manually eyeballing the logs looking for a message you’re already doing it wrong. Use search, have ids in the messages etc.
Remember folks, debug logging on because if it’s not logged, when it breaks you don’t have the logs…
That would be the levelname part. But if your log aggregator or subsystem is hindering your ability to use your logs, I would look to solve that problem before worrying about anything within your application.
Even storing logs in a format that you need to decode or download would be a red flag for me. Seconds of debugging all of a sudden turns into minutes or even hours.
I think this is a good overview, I especially like "descriptive, contextual, reactive." I like to ask "who is going to see this message and why? What action should they take?"
I've also come to find a few "wide" log entries significantly better than having many smaller log messages (especially as the system grows).
Ideally, one operation == one log message, and contains all context: userid, sessionid, url path, domain, error codes/messages, timing, etc. log error/warning if it fails, info if success. It's much easier to follow than one operation spread across a half dozen log messages. In dev, with one thing happening at a time, it's no big deal, but in production there's way more stuff happening and it is interspersed with hundreds of lines of logs of other operations as well as other threads running the same operation concurrently.
Does anyone ever log in multi dimensional way at all?
Everyone seems to just go,
logger.info('Doing that')
But logs really should be covering the context instead of being single dimensional by being placed at the execution point, which will also make the code far more readable.
//Sorry, I don't know python well but trying to run a lambda as a parameter.
myLogger.info('Doing that', lambda : (
doThat()
whatNot()))
And then, you know exactly what the log is covering as well as take a benchmark of the said part and report how long it took to run.
You don't need 'Done that' logging, as if you throw inside, the log doesn't happen.
You might want to know 'Doing that' was run even if it threw inside, but if logging is paired with an error reporting tools like Sentry, which is quite essential than depending on simple logging, you can know the stack trace easily to track which part of the code was run.
It seems no logging libraries do it the multidimensional way but it's an essential part of how I do logging.
Honestly, I like to keep the logger as decoupled and minimalist as possible. There’s https://vector.dev which can basically ship your logs from source A to destination B (supports tonnes of usecases). Separation of concerns makes things much more easier.
Maybe it's Stockholm syndrome, but contrary to what seems like most people I don't actually mind the built in logging library. Sure, it reeks of its Java roots and can be a bit of a pain to set up configure, but once that's done it's incredibly flexible and generally works really well.
One of the main gripes I do have with it is its reliance on the old-school %-based formatting for log messages:
logger.debug("Invalid object '%s'", obj)
As there are real advantages to providing a template and object args separately, this is a bit of a shame since it pushes people to use pre-formatted strings without any args instead.
I fixed this for myself by writing bracelogger[0]. If this is a pain point for you too, you might find it useful.
Ex:
logger.debug("Invalid object of type {0.__class__.__name__}: {0}", obj)
import pygogo as gogo
kwargs = {'contextual': True}
extra = {'additional': True}
logger = gogo.Gogo('basic').get_structured_logger('base', **kwargs)
logger.debug('message', extra=extra)
# Prints the following to `stdout`:
{"additional": true, "contextual": true, "message": "message"}
Best way to find logs connected to one of your API requests is by using correlation IDs, which are injected to each log message. Me and my friend wrote libraries to do this for both Django[1] and ASGI apps(starlette, FastAPI)[2]
In the first example, the author says not to log who the user is if a connection is successful, only if it fails, because if it succeeds there's nothing you need to do. If that's true then why log it?
given you’ve configured logging somewhere early on in the bootstrap phase of your app - there’s really few reason to go up and above having more than these two lines in all your logging modules
I mean, yes, what you said isn’t wrong, that is what you get but
a: logging is effectively a global singleton object already
b: other than less pasta, are there any benefits to saving a logger import? In the case of logging it would seem you would lose all the benefits of “__name__” that are mentioned in the article (which to reiterate are considered best practice)
anyone else just define a function log(msg) the prints to stderr or maybe stdout and use that instead for simple programs/daemons? I never really got the big value proposition of seven-leveled logging or the complexity of it. If I need to customize it I just change my log function.
That works for most cases, but many 3rd party libraries (like requests) integrate with the built in logging library, so if you want to log that info you're back to working with the stdlib logging
One of the biggest logging mistakes I see is people misusing Error. What most developers consider an error -- external service call failed, user gave bad input, or a timeout happened - is often not really a problem. The service call is re-tried. Users are going to user (and provide garbage data and then fix it).
None of these require operator intervention.
To me, Errors imply action needed, or highlight an unresolved situation. If the service call keeps failing after all retries, and now a feature is impacted (eg a user won't get a report, or there's a gap in data somewhere) then that can be an Error.
All the temporary faults are useful as Warn to highlight them and distinguish from other normal operations, but no action is needed. This is most useful when a user reports something like "it seems to be taking much longer than usual to get email notifications" and when an operator looks at the logs, they're full of warnings. It's also useful for monitoring: high number of warnings in the log can cause a non-critical notification to operators (during business hours; not a wake-me-up-at-2am page).
I really wanted to have an app with a reasonable default level, then allow flags like --debug, --verbose plus --quiet and it never seemed to map like I wanted.
Just try reading logs from journalctl, where you can filter the levels you don't need and see errors and warnings in a different colour. Then you will perhaps re-evaluate the importance of levels.
Things I really dislike about it is the lack of “context”. Usually log messages are about something - often a request. You can’t attach a request ID or something else a nested set of function calls that log.
The whole library is just really rubbish and has not aged well. There’s no standard way of outputting JSON logs, but there’s a built in way to spawn a socket server that allows the logging configuration to be updated remotely via a bespoke protocol? And everything is built mostly around logging to files.
It also hits that perfect sweet spot of being both overly engineered and totally inflexible. I wanted to funnel our log messages to s3 via the “s3fs” module, which supports a “file like” object that gets written to s3. I had to hack around the various handlers to support this because it assumes it’s a “real” file.
Hate it.