13 ms·

Logging in Python like a pro

307 points by EntICOnc 4y ago

miohtama 4y ago
A very good post on creating good log contexts. For powerful log channeling and notifications to Telegram, Slack, etc. there is this Python package: https://pypi.org/project/notifiers/ https://pypi.org/project/notifiers/ I also created a logging handler for Discord, where one can get notifications on errors to a private channel: https://github.com/tradingstrategy-ai/python-logging-discord-handler https://github.com/tradingstrategy-ai/python-logging-discord...
poopman68686 4y ago
Good Post!
efitz 4y ago
Very good advice. 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.
- jstarfish 4y ago
  My standard, to the extent possible: make your logs clear enough that your attorney would be able to understand them. You may well find yourself wishing you did this if you also output DEBUG logs in production.
- AmpsterMan 4y ago
  I don't know if it's the way cloud watch works in my current company or what, but I preferred SSH into the server and grep for what I want lol. I miss that I can't do that any longer
  - dygd 4y ago
    Using the official CLI (aws logs get-log-events) or https://github.com/jorgebastida/awslogs https://github.com/jorgebastida/awslogs is pretty close to SSH-ing and grepping.
    - AmpsterMan 4y ago
      Oh thanks I'll have to give that a shot! It may also just be that I need to not get so caught up in learning a new way to do something.
  - efitz 4y ago
    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.
- dragonwriter 4y ago
  > 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.
  - efitz 4y ago
    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
    - deleted 4y ago
      [deleted]
- pid-1 4y ago
  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.
  - OJFord 4y ago
    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?)
connorbrinton 4y ago
Another great project for Python logging is loguru: https://loguru.readthedocs.io/en/stable/overview.html https://loguru.readthedocs.io/en/stable/overview.html 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
- isoprophlex 4y ago
  Cannot recommend loguru highly enough. After a coworker showed it to me, I fell in love immediately. I'll never go back to that rancid pile of shit that is the builtin logger lib.
- codethief 4y ago
  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…
  - pnt12 4y ago
    I think it may even have more global state than standard logging. This is the standard approach to produce a log: ```from loguru import logger logger.info("hello world") ``` But betteid avise you to research more, because the library is nice to use and is well documented.
    - codethief 4y ago
      Thanks, I'll have a look then!
- 4y ago
orf 4y ago
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. Hate it.
- formerly_proven 4y ago
  It's unfortunate how blind copying of log4j into many languages seems to have inhibited improvements in logging in the last ~20ish years.
- systemvoltage 4y ago
  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.
  - oefrha 4y ago
    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.
    - txru 4y ago
alanwreath 4y ago
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 import logging logger = logging.getLogger(__name__) But boy oh have I seen some funny business where people attach the logger to their objects like so class Wat: def __init__(self): self.logger = logging.getLogger(…) All for what? For WAT?!
- 1337shadow 4y ago
  To inherit the logger attribute in subclasses?? Save an import?
  - alanwreath 4y ago
    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)
    - xgstation 4y ago
- Nimitz14 4y ago
  That is a super common mistake from beginner python programmers.
mr-karan 4y ago
Honestly, I like to keep the logger as decoupled and minimalist as possible. There’s https://vector.dev 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.
Thaxll 4y ago
Don't use warn, either info or error nothing in between.
- m463 4y ago
  I disliked the logging levels 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. maybe it's obvious and I just don't see it.
  - LtWorf 4y ago
    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.
  - 1337shadow 4y ago
    By default, use INFO to tell what has been done, use DEBUG to describe what's going to be done and how it's deciding it.
- gregmac 4y ago
  Warning is actually very useful. 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).
aunty_helen 4y ago
"%(asctime)s - %(levelname)-5s - %(name)-20.20s - %(message)s - (%(filename)s:%(lineno)s)" 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…
- LtWorf 4y ago
  If I can't query for warning level on journalctl it's useless.
  - aunty_helen 4y ago
    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.
- raylad 4y ago
  This is the way. You should be able to immediately tell from looking at any log entry: * When it happened * How serious it is (Informational, Warning, Error, Fatal - at a minimum) * Type of issue (ideally a unique issue type from a list of known issue types) * Who logged it (system / subsystem / module / line number) * What happened (including any germane variable values)
memco 4y ago
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.Logger.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.
- Narushia 4y ago
  I second this, very useful. I kind of expected the article to mention it, but it didn’t!
- atorodius 4y ago
  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. ```
- pR0Ps 4y ago
  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. Ex: logger.debug("A non-critical exception occurred", exc_info=True)
jasonpeacock 4y ago
This is very long (but thorough!) article about implementing structured logging. Shorter version: Use structured logging! If using Python, use `structlog`: https://www.structlog.org/en/stable/ https://www.structlog.org/en/stable/
- timost 4y ago
  I agree, structlog is such a quality of life improvement. It can be tricky to forward all logs through it [0] but it's definitely worth it. [0] https://www.structlog.org/en/stable/standard-library.html https://www.structlog.org/en/stable/standard-library.html
  - jteppinette 4y ago
    https://github.com/jteppinette/python-logfmter https://github.com/jteppinette/python-logfmter I made this library to make global structured logging in Python super easy.
- delijati 4y ago
  You always need some boilerplate to get structlog working. I always use this (author) to have the needed defaults https://github.com/peakiq/logma https://github.com/peakiq/logma.
- matheusmoreira 4y ago
  Thank you so much for posting this. Very well designed library. I wish logging worked like this on every language.
deleted 4y ago
[deleted]
gregmac 4y ago
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.
jxramos 4y ago
This is the first time I've ever learned about that `extra` argument to logging calls Interesting capabilities. There's a rundown with log output examples seen in https://docs.python.org/3/library/logging.html#logging.Logger.debug https://docs.python.org/3/library/logging.html#logging.Logge...
bakpakin 4y ago
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.
- bbkane 4y ago
  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
kordlessagain 4y ago
As a logger in a previous lifetime, I approve of this content.
hotfixguru 4y ago
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] [1] https://github.com/snok/django-guid https://github.com/snok/django-guid [2] https://github.com/snok/asgi-correlation-id https://github.com/snok/asgi-correlation-id
mekster 4y ago
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.
frays 4y ago
Great article. Didn't know about the `extras` keyword.
reubano 4y ago
I'd just like to plug my lib, pygogo (https://github.com/reubano/pygogo https://github.com/reubano/pygogo). Here's a structured log example taken from the docs. 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"}
pR0Ps 4y ago
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) [0]: https://github.com/pR0Ps/bracelogger https://github.com/pR0Ps/bracelogger
Jeff_Brown 4y ago
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?

307 points by EntICOnc 4y ago

A very good post on creating good log contexts. For powerful log channeling and notifications to Telegram, Slack, etc. there is this Python package: https://pypi.org/project/notifiers/ https://pypi.org/project/notifiers/ I also created a logging handler for Discord, where one can get notifications on errors to a private channel: https://github.com/tradingstrategy-ai/python-logging-discord-handler https://github.com/tradingstrategy-ai/python-logging-discord...

poopman68686 4y ago

Good Post!

efitz 4y ago

Very good advice. 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.

jstarfish 4y ago
My standard, to the extent possible: make your logs clear enough that your attorney would be able to understand them. You may well find yourself wishing you did this if you also output DEBUG logs in production.
AmpsterMan 4y ago
I don't know if it's the way cloud watch works in my current company or what, but I preferred SSH into the server and grep for what I want lol. I miss that I can't do that any longer
- dygd 4y ago
  Using the official CLI (aws logs get-log-events) or https://github.com/jorgebastida/awslogs https://github.com/jorgebastida/awslogs is pretty close to SSH-ing and grepping.
  - AmpsterMan 4y ago
    Oh thanks I'll have to give that a shot! It may also just be that I need to not get so caught up in learning a new way to do something.
- efitz 4y ago
  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.
dragonwriter 4y ago
> 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.
- efitz 4y ago
  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
  - deleted 4y ago
    [deleted]
pid-1 4y ago
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.
- OJFord 4y ago
  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?)

connorbrinton 4y ago

Another great project for Python logging is loguru: https://loguru.readthedocs.io/en/stable/overview.html https://loguru.readthedocs.io/en/stable/overview.html 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

isoprophlex 4y ago
Cannot recommend loguru highly enough. After a coworker showed it to me, I fell in love immediately. I'll never go back to that rancid pile of shit that is the builtin logger lib.
codethief 4y ago
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…
- pnt12 4y ago
  I think it may even have more global state than standard logging. This is the standard approach to produce a log: ```from loguru import logger logger.info("hello world") ``` But betteid avise you to research more, because the library is nice to use and is well documented.
  - codethief 4y ago
    Thanks, I'll have a look then!
4y ago

orf 4y ago

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. Hate it.

formerly_proven 4y ago
It's unfortunate how blind copying of log4j into many languages seems to have inhibited improvements in logging in the last ~20ish years.
systemvoltage 4y ago
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.
- oefrha 4y ago
  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.
  - txru 4y ago

alanwreath 4y ago

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 import logging logger = logging.getLogger(__name__) But boy oh have I seen some funny business where people attach the logger to their objects like so class Wat: def __init__(self): self.logger = logging.getLogger(…) All for what? For WAT?!

1337shadow 4y ago
To inherit the logger attribute in subclasses?? Save an import?
- alanwreath 4y ago
  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)
  - xgstation 4y ago
Nimitz14 4y ago
That is a super common mistake from beginner python programmers.

mr-karan 4y ago

Honestly, I like to keep the logger as decoupled and minimalist as possible. There’s https://vector.dev 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.

Thaxll 4y ago

Don't use warn, either info or error nothing in between.

m463 4y ago
I disliked the logging levels 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. maybe it's obvious and I just don't see it.
- LtWorf 4y ago
  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.
- 1337shadow 4y ago
  By default, use INFO to tell what has been done, use DEBUG to describe what's going to be done and how it's deciding it.
gregmac 4y ago
Warning is actually very useful. 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).

aunty_helen 4y ago

"%(asctime)s - %(levelname)-5s - %(name)-20.20s - %(message)s - (%(filename)s:%(lineno)s)" 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…

LtWorf 4y ago
If I can't query for warning level on journalctl it's useless.
- aunty_helen 4y ago
  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.
raylad 4y ago
This is the way. You should be able to immediately tell from looking at any log entry: * When it happened * How serious it is (Informational, Warning, Error, Fatal - at a minimum) * Type of issue (ideally a unique issue type from a list of known issue types) * Who logged it (system / subsystem / module / line number) * What happened (including any germane variable values)

memco 4y ago

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.Logger.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.

Narushia 4y ago
I second this, very useful. I kind of expected the article to mention it, but it didn’t!
atorodius 4y ago
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. ```
pR0Ps 4y ago
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. Ex: logger.debug("A non-critical exception occurred", exc_info=True)

jasonpeacock 4y ago

This is very long (but thorough!) article about implementing structured logging. Shorter version: Use structured logging! If using Python, use `structlog`: https://www.structlog.org/en/stable/ https://www.structlog.org/en/stable/

timost 4y ago
I agree, structlog is such a quality of life improvement. It can be tricky to forward all logs through it [0] but it's definitely worth it. [0] https://www.structlog.org/en/stable/standard-library.html https://www.structlog.org/en/stable/standard-library.html
- jteppinette 4y ago
  https://github.com/jteppinette/python-logfmter https://github.com/jteppinette/python-logfmter I made this library to make global structured logging in Python super easy.
delijati 4y ago
You always need some boilerplate to get structlog working. I always use this (author) to have the needed defaults https://github.com/peakiq/logma https://github.com/peakiq/logma.
matheusmoreira 4y ago
Thank you so much for posting this. Very well designed library. I wish logging worked like this on every language.

deleted 4y ago

[deleted]

gregmac 4y ago

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.

jxramos 4y ago

This is the first time I've ever learned about that `extra` argument to logging calls Interesting capabilities. There's a rundown with log output examples seen in https://docs.python.org/3/library/logging.html#logging.Logger.debug https://docs.python.org/3/library/logging.html#logging.Logge...

bakpakin 4y ago

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.

bbkane 4y ago
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

kordlessagain 4y ago

As a logger in a previous lifetime, I approve of this content.

hotfixguru 4y ago

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] [1] https://github.com/snok/django-guid https://github.com/snok/django-guid [2] https://github.com/snok/asgi-correlation-id https://github.com/snok/asgi-correlation-id

mekster 4y ago

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.

frays 4y ago

Great article. Didn't know about the `extras` keyword.

reubano 4y ago

I'd just like to plug my lib, pygogo (https://github.com/reubano/pygogo https://github.com/reubano/pygogo). Here's a structured log example taken from the docs. 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"}

pR0Ps 4y ago

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) [0]: https://github.com/pR0Ps/bracelogger https://github.com/pR0Ps/bracelogger

Jeff_Brown 4y ago

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?