Nathaniel's Quick And Dirty Python Logging Lesson

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 print function, but it is much more powerful than print. Every logging event has a message, but also records other information like line number and module name.

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')

Which outputs: [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) .debug(), .info(), .warning(), .error(), and .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 stdout:

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: del logging.getLogger('logger_name').handlers[:].

Formatting logs

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)

You have access to all sorts of parameters when you build your format string, you can check them out in the python docs. Tip: the syntax is just old-style Python string formatting.

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 <package_name>.<module_name>.

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 logging.getLogger("requests.packages.urllib3.contrib.pyopenssl").

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

Filtering logs

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 DEBUG or 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.

Logger Recipes

The easiest configuration

The logging module includes a convenience function for configuring the root logger in one line. To setup a streamhandler:

logging.basicConfig(level=logging.DEBUG)

To set up a file logger:

logging.basicConfig(filename='my_app.log', level=logging.DEBUG)

Check out the options for basicConfig in the Python docs.

Some off-the-shelf format strings.

See the docs for all available fields.

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.

Logging exceptions

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 = 'loggingnerd@hotmail.com'
stmp_password = '12345'
from_email_address = 'error@logging.co'
to_email_addresses = ['loggingnerd@hotmail.com']
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))

Conclusion

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.