Written May 21, 2017
Logging should be easy. If you are overwhelmed with logging output you can't filter or turn off, or you don't know how to tap into a misbehaving libraries logging, this post is for you.
The absolute basics
A logger is an object that records events. You use it like you would use the
Here is a simple logging example:
import logging fmt_str = '[%(asctime)s] %(levelname)s @ line %(lineno)d: %(message)s' # "basicConfig" is a convenience function, explained later logging.basicConfig(level=logging.DEBUG, format=fmt_str) logger = logging.getLogger(__name__) logger.debug('hello logged world')
[2017-05-19 21:16:17,821] DEBUG @ line 6: hello logged world
There are five different levels of severity that a log event can have. Each one has it's own method to log an event. The methods are (in order of severity)
.critical(). These levels can be used to filter log output, as explained in the section Filtering logs. That's all you need to know to get started, but if you want to become a Python-Logging-Zen-Master, read on.
IMPORTANT LESSON #1: All loggers are global
You can have many loggers, and every logger has a name. You can get any logger by name with
logging.getLogger("name_of_logger"). If the logger doesn't already exist, it will be created. All loggers can be accessed from anywhere in your code using this method, so all loggers are global. Some people create a logger in one module and then import it into other modules, but this increases the coupling between modules so it's not a great idea.
What you really want is
logger = logging.getLogger(__name__) near the top of every module. What is
__name__? It is the name of your module. If your module is part of a package,
__name__ will be
package_name.module_name. This is what you want, don't pick your own name!!!
Displaying and/or storing logs
By default a logger doesn't do much. If you run this code:
import logging logger = logging.getLogger(__name__) logger.info('Something has happened!')
You will get no output. If you change
logger.info('Something has happened!') to
logger.warning('Something has happened!') something will happen, but not much. In Python 3.6 it prints
Something has happened!. In Python 2.7 it prints
No handlers could be found for logger "__main__".
To start controlling your logging output, you need a handler. A handler formats and sends your logs somewhere you can look at them. Examples of "somewhere" could be stdout, an email, another server or a file. Here is a basic example that prints to
import logging logger = logging.getLogger(__name__) handler = logging.StreamHandler() logger.addHandler(handler)
There are lots of different handlers you can use, like
logging.FileHandler, and many more in the
logging.handlers package (you need to
import logging.handlers as it is not imported into
logging by default). The handlers a logger is attached to are stored in the logger's handler attribute as a list. You can clear them out with:
Every handler has a formatter that determines how the logs are output. The default logging output for a handler does not give much information, but you can change this by creating a formatter using a format string, and setting it on your handler:
formatter = logging.Formatter('[%(asctime)s] %(levelname)s @ line %(lineno)d: %(message)s') handler.setFormatter(formatter)
IMPORTANT LESSON #2: All loggers are part of one tree
If you create a new logger in every module, do you have to set handlers and formatters on each one? No! If you did that, changing your logging configuration would be a nightmare. Luckily Python adds all loggers to a single "logging tree," and you can add handlers to the whole tree, or to different sections of the tree. Every logger has a parent, and passes log events to it's parent. The only exception is the root logger, which all other loggers descend from. The root logger can be obtained with
logging.getLogger() (no arguments).
Where a logger sits in the logging tree is determined by its name. If there are no periods in the name, the logger is a child of the root logger. If you have a period in your logger name, like
<parent name>.<child name>, then that logger will be a child of
<parent name>. If you don't create
<parent name> it will be created for you. If you use
__name__ as your logger name in each module, your package structure will have a matching logging structure because the
__name__ of a module in a package is
To help visualize this, install logging_tree (run
pip install logging_tree). Run this python code after importing the packages or modules you want to check the logging setup of:
import logging_tree logging_tree.printout()
Here is some example output (it's truncated a bit):
<--"" Level WARNING | o<--[fuel_scrapes] | | | o<--"fuel_scrapes.base" | | Level NOTSET so inherits level WARNING | | | o<--"fuel_scrapes.fleetone" | Level NOTSET so inherits level WARNING | o<--"requests" | Level NOTSET so inherits level WARNING | Handler <logging.NullHandler object at 0x104ff1610> | | | o<--[requests.packages] | | | o<--"requests.packages.urllib3" | Level NOTSET so inherits level WARNING | Handler <logging.NullHandler object at 0x104ff1590> | | | o<--"requests.packages.urllib3.connection" | | Level NOTSET so inherits level WARNING | | | o<--"requests.packages.urllib3.connectionpool" | | Level NOTSET so inherits level WARNING | | | o<--[requests.packages.urllib3.contrib] | | | | | o<--"requests.packages.urllib3.contrib.pyopenssl" | | Level NOTSET so inherits level WARNING | | | o<--"requests.packages.urllib3.poolmanager" | | Level NOTSET so inherits level WARNING | | | o<--"requests.packages.urllib3.response" | | Level NOTSET so inherits level WARNING | | | o<--[requests.packages.urllib3.util] | | | o<--"requests.packages.urllib3.util.retry" | Level NOTSET so inherits level WARNING
You can see how the tree structure looks a lot like a package structure both for "fuel_scrapes" (a module I wrote) and for "requests" (a third-party module).
A nested logging tree like this is great because you can configure just the section of the tree that you want. For example, if I'm having general issues with the
requests module, I could grab the
requests logger with
logging.getLogger("requests") and set the a stream handler with a level of DEBUG (more on levels next). Then I will get debugging information from requests, without cluttering the output with debugging information from
fuel_scrapes. If I know my issue is with a bad SSL connection, I can get even more specific and grab the appropriate logger with
This tree structure also means that you don't have to worry about making too many loggers. You can always gather logs for an entire section of your application by moving "up the tree."
Every logger and every handler can have a "level" that acts as a threshold for passing on or recording logging events. All events that reach a logger or handler that are below the set level are ignored. If you are not seeing some logging you expected, it's probably because a level somewhere in the logging tree is blocking it. Levels have numeric constants:
- CRITICAL --> 50
- ERROR --> 40
- WARNING --> 30
- INFO --> 20
- DEBUG --> 10
- NOTSET --> 0
You can set the level for a handler or logger with
logger_or_handler.setLevel(logging.LEVEL). For example,
logger.setLevel(logging.DEBUG). If a logger's level is
NOTSET (the default for new loggers), it inherits its level from its parent. The default level for the root logger is
WARNING, so generally all other loggers inherit the level
WARNING and you never see any of the
INFO messages until you configure your loggers.
If you can't figure out why some logs are being filtered out, there are three places to look:
- The level on the logger you want to see messages from
- The level on all the ancestors between that logger and the logger that your handler is attached to
- The level on your handler itself
IMPORTANT LESSON #3: Where to configure your loggers
You should configure your loggers close to the "start" or "entry point" of your application. That way it is easy for people to find, and if you reuse some supporting modules those modules will not have annoying logger configuration built into them. If you reuse a certain configuration across several entry points, write a function to setup your logging.
The easiest configuration
The logging module includes a convenience function for configuring the root logger in one line. To setup a streamhandler:
To set up a file logger:
Check out the options for
basicConfig in the Python docs.
Some off-the-shelf format strings
old_reliable = "%(asctime)s-%(levelname)s-%(module)s:%(lineno)s %(message)s" absolutely_everything = ("%(levelname)s in %(filename)s:%(funcName)s " "at line %(lineno)d occured at %(asctime)s\n\n\t%(message)s\n\n" "Full Path: %(pathname)s\n\nProcess Name: %(processName)s")
Adding color to your logs
You can quickly add some color to your logs using colorlog. Install with
pip install colorlog and use with:
import colorlog handler = colorlog.StreamHandler() handler.setFormatter(colorlog.ColoredFormatter( '%(log_color)s%(levelname)s:%(name)s:%(message)s')) logger = colorlog.getLogger('example') logger.addHandler(handler)
This makes things a bit easier to read.
There is a convenience logging method that does a great job of recording exceptions:
try: 1/0 except Exception: logger.exception('Something has gone terribly wrong!')
gives output something like this (depending on your formatter):
[2017-05-21 20:01:28,073] ERROR @ line 4: Something has gone terribly wrong! Traceback (most recent call last): File "my_module.py", line 2, in <my_func> 1/0 ZeroDivisionError: integer division or modulo by zero
Often exceptions are one of the most important things to log, so getting exception logging working is a really good idea. Generally you want to catch errors as "high up" in your code as possible, like a try-except around the call to your
main() function. In web apps there is usually an error handler you can stick this in.
Sending logs via email
If you have some scripts running as cron jobs or as Windows scheduled tasks it is a good idea to setup email logging so that you will know when things go wrong. This is pretty easy:
smtp_server = 'smtp.hotmail.com' smtp_port = 587 smtp_username = 'firstname.lastname@example.org' stmp_password = '12345' from_email_address = 'email@example.com' to_email_addresses = ['firstname.lastname@example.org'] subject = "You've got logs" mail_handler = logging.handlers.SMTPHandler((smtp_server, smtp_port), from_email_address, to_email_addresses, subject, secure=tuple(), credentials=(smtp_username, stmp_password))
Make a new logger in every module!!! Configure your handlers, formatters, and log levels at the "top" of your application, near your entry point. Packages and modules that are reused across projects should create and use loggers, but not configure them.
Feedback on this post is welcome! Please comment below.