Python logging best practices
Logging is one of those things that, being orthogonal to actually getting something done, many developers fail to learn the nuances of. So I want to go over a few things I had to learn the hard way:
We are blessed in the python community because we have the wonderful ‘logging’ module in our standard library, so there is no barrier to entry or excuse to not use proper logging mechanisms. There are often reasons to roll your own of something, that something will probably never be logging. Don’t do it (this goes for all major languages).
The logging module is incredibly flexible. The ‘handlers’ are the key to leveraging the power of the logging module. Handlers can do pretty much whatever you want them to do. Once you get past the most basic logging, you should start reading up on Handlers. Understanding handlers is the key to understanding logging, in my experience.
Root-level configuration should generally only be done by the application, not any library modules. Ie, ‘logging.basicConfig’ should only be (and usually can only be) called very early on. Examples of root-level configuration are setting the format of the logs, setting the logs to print to stdout/stderr, etc. Anything that has to do with global state (and streams are examples of global state), should be handled by the application, never by a library. Rarely should you add a StreamHandler. A FileHandler for a single logger can be useful in some cases (like, if you have a server that is part of a larger application) but should generally be avoided.
If you have multiple classes in a file, give them each their own logger. Do not use a single module logger for many classes. Identify the logger by the class name so you know what logger produced what log.
Putting self.logger = logging.getLogger(type(self).__name__) on a base class is a good way to get a unique logger for each subclass, without each subclass having to set up their own logger.
logger.<methodname>('spam, eggs, and %s', myvar) should be used instead of logger.<methodname>('spam, eggs, and %s' % myvar), as it saves a string formatting.
Make a module with your commonly used log format strings, so each developer doesn’t have to come up with their own, and you achieve some standardization.
Almost never use printing. Use logging, and set your logger(s) up to log to stdout with a StreamHandler while you are debugging. Then you can leave your ‘prints’ in, which will make life easier when you need to go back in to find bugs.
You almost never want to catch, log, and re-raise. Let the caller be responsible for logging and handling the error, at the level it can be handled properly. Imagine if at every level, every exception was logged and re-raised. Your log would be a mess!
I consider the levels are follows- DEBUG only for developers, INFO for general internal usage, WARNING for deployment (I don’t know why you’d have your log level set higher than WARNING). Another way of thinking about them is, DEBUG has all information which only developers care about, INFO has little enough information that the stuff there is relevant and enough that problems can be diagnosed by a technical person, and WARNING will just tell you when something goes wrong. I wouldn’t make any more fine-grained levels than this, but it is up to you and your team to figure out where to use what. For example, do you log every server and client send/recv as DEBUG or INFO? It depends, of course.
The more library-like your code, the less you generally log. Your library should be clear, working, and throw meaningful exceptions, so generally your real library-libraries shouldn’t even need to log.
Logging is not a replacement for raising exceptions. Logging is not a way to deal with exceptions, either.
Remember these are guidelines only (and my guidelines). There are always exceptions to these rules (no pun intended).
I have a feeling those of you writing web/server apps are more familiar with logging best practices than those of us writing code in client apps. But these are all things I’ve seen in the real world so I thought them worth giving my two cents about them. What are your logging guidelines?
I agree with many of the things you say, but disagree on some points:
1. Python does not force you to use OO, and for those people who use functional styles (or a mixture), using __name__ as the logger name is the best practice. Using the type(self).__name__ gives you the unqualified name of the class, which in a large system may occur in a number of different packages. Possibly ‘%s.%s’ % (type(self).__module__, type(self).__name__) is more useful, as it allows filtering of all classes in a module using just the module name.
2. Logging in libraries shouldn’t be discouraged. For example I was just looking at a problem with PPTP connections working to a server from one machine but not another. The PPTP protocol code handling is in a library, but luckily it uses logging, so I could see what was happening under the hood.
A library is meant to be used as a black box, but library developers are just like the rest of us in terms of not necessarily having thought of all corner cases. Faced with imperfect software, logging is one of the few ways you can look into a running system in production without bringing it down. That goes for both the application and its libraries.
Just my 2 cents.
Vinay, when you comment on logging it isn’t two cents, it is more like several dollars :) Glad you read the post and commented.
On point #1, I agree. But if you are using functional styles, and are minimizing your use of mutable state, I think you should have less need of logging (see next point).
Regarding logging in libraries (point #2), I suppose like many ‘best practices’ we establish, they are reactions against clearly bad practices and replacing them with the opposite is rarely the best thing. So the discouragement of logging in libraries comes down to two things: a) The less state your library stores and/or mutates, the better, and if you’re not storing or mutating, you can generally get away with raising errors that convey the failed information and not having to log. b) Likewise, your library should have clear contracts where logging in the case of a failure and not raising is never acceptable. But of course this is all relative and imperfect, and people should use their best judgement- if people are going to write crappy libraries, the advice about logging isn’t going to make it much better or worse.
I’m not sure that logging should be tied to whether you store or mutate state. In the PPTP example I gave above, there was no storing or mutating of state: however, the client was passing an implicit Windows domain, which was causing authentication failure even though the username and password were correct. Now an authentication failure is not even an exception-raising condition: however, setting verbose logging allowed me to see what the problem was.
I would say that the usage of logging should be wider than just the exception cases (of course, based on the developer’s discretion).
On the question of logging and re-raising: I think it’s best to log and handle at one level if possible, but sometimes it’s not unreasonable to log at a low level and raise a conceptually higher-level exception which makes sense at the relevant level (for example, low level SQL exception is logged and a higher level ORM exception is raised. The logging of the SQL exception aids the ORM library developer – knowing why the ORM exception was raised – but the ORM-level exception aids the ORM user, because it is couched in ORM concepts).
Regarding that Windows domain, was the library itself doing IO to authenticate? As I should have said in the article, IO is a good thing to log, and is definitely one place you want to log more than just the exception cases, like you say. For example I always log everything I send/receive to/from several of the local services we run our tools against.
In response to logging and re-raising: What I meant is, this is pointless (though not uncommon) code:
try:foo()
except Exception:
logger.error(...)
raise
If you have more than the naked ‘raise’ statement that raises the current exception (well whatever the precise technical description is for what it does), clearly there is a reason to log.
Well, it was getting the credentials (including domain) across the network.
[example snipped]
I agree with that – no need to log and just “raise”.