Power-Up Your Python Logging

A guide to take you from beginner to pro with Python’s built-in logging tools

Debugging a large application sucks. Especially when you have a bug that shows itself in production but can’t be reproduced in the dev environment. Finding these can be made easier with the use of Python’s built-in logging tools.

This guide is designed to help newcomers understand Python’s logging module. Heaven knows it confused me when I first started. In the end, we will have a working logger that is able to throw errors to a discord channel.

The code for this problem can be found in the civicsoft/ieddit GitHub repository.

Quick Overview of Logging

One note before we get into logging: both loggers and handlers below use, what we call, levels. This is a hierarchy of how things are handled.

For example, when we set a handler to the DEBUG level, it will receive debug statements and all the levels above it. These levels are used to filter data by its importance.

Loggers

A logger is simply a named instance of the logging object. All loggers are “global” within your program. Here is an example of what that looks like.

We have defined a logger named app in app.py.# ieddit/app.pyimport logging
logger = logging.getLogger("app")

Now, if we wanted to, we could drop into another file and have access to that same logger instance we created before.

This is what that would look like:# ieddit/utils.pyimport logging
logger = logging.getLogger("app")

Now the utils.py has access to that same logger instance! This means that we can declare all the loggers we want before they are ever needed, which we will see a little later.

Side note here: the best practice is to use the __name__ attribute for naming loggers like this: logging.getLogger(__name__). This way, each file has its own unique logger name.

Logger’s core job is to send LogRecords out to different handlers. LogRecords capture the details of what happened when they were called.logger.info("Emitting Info LogRecord")
logger.error("Emitting Error LogRecord")

Above is an example of what it means to emit an event. Events are emitted with a level attached. This lets the logger know how urgent the LogRecord is.

The problem with the code above is that we haven’t told the logger where these records are supposed to go. This is where handlers step in.

Handlers

The handlers control where the LogRecords go. Handlers are standalone objects that can be attached to logger instances.logger = logging.getLogger(__name__)
fileHandle = logging.FileHandler('ieddit.log')
logger.addHandler(fileHandle)

The above code is telling the logger that, any time a LogRecord is created, it should be sent to the file ieddit.log. The problem right now, is that ieddit.log will get stuffed with a ton of logs.

Setting the level that a handler is supposed to manage helps us filter down our logs.logger = logging.getLogger(__name__)
fileHandle = logging.FileHandler('ieddit.log')
fileHandle.setLevel(logging.WARNING)
logger.addHandler(fileHandle)logger.info("This won't show in ieddit.log")
logger.error("This will show.")

Above is how we can use the level to filter out logs. Using the chart from the beginning of this section, we can see that ERROR is higher than WARNING so it will be handled. Info is below warning so the handler will ignore that record.

There are several types of handlers that can be used. For the complete list, see the documentation for handlers.

StreamHandler will send output to the console. File handlers send info to an output file. The most dynamic handlers are the QueueHandler and QueueListener, but more on those later.

Formatters

Only having a message saying: “There was an error” isn’t helpful. This is where the formatters come in. Formatters live on handlers as the handlers process the log records.

They can add additional information, such as where, what, why, when, and how.logger = logging.getLogger("__main__")
consoleHandle = logging.StreamHandler()
consoleHandle.setLevel(logging.INFO)# Setup the formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
consoleHandle.setFormatter(formatter)logger.addHandler(consoleHandle)logger.info("Message")>>> 2019-10-25 00:01:42,283 - __main__ - INFO - Message

Above is the output in the console that was created.

The formatter inserts the time, logger name, level of the record, and message. Note here we put __main__ in manually but if you use __name__ it will be the module name here.

Top to Bottom

This is what we know so far about logging.

First, we create a logger that can be accessed by its name anywhere. This logger creates log records with an associated level. Those records are handled by one or more of the handlers that are associated. If there is a formatter present the handler will format the output accordingly.

QueueHandler and QueueListener

Now here is where the real fun starts. Anytime you put logger.info(“message”) into your code, your program has to wait for that to finish.

Not a big problem if you are simply outputting to the console, right?

If you send logs to a database, waiting for the record to be created could take some time. Then, your program would need to pause every time a log record is created.

This is where the QueueHandler and QueueListener come in. QueueHandler puts the message in a queue that lives on a separate thread. Then, QueueListener steps in to send the log record to all the other handlers.

This way, your program doesn't have to stop to wait for the log record to be created.

Here, I will point you to Rob Blackbourn’s article, How to use Python logging QueueHandler with dictConfig. To save length here, I will tell you to read his article and come back here to see how this can be used in our custom logger.

Add the code from his article into a file named something like logging_util.py.# run.py
import logging_util
import logging
from queue import Queue# Initialize Logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.WARNING)fileHandle = logging.FileHandler('ieddit.log')
queueHandle = logging_util.QueueListenerHandler(
                                    queue=Queue(-1),
                                    handlers=[fileHandle])logger.warning("Ack!")

In the above example, the data will flow like this:Warning Log Record Created
  |
  V
Log record added to QueueHandler on separate thread
-> Main program is no longer blocked
  |
  V
QueueListener picks up the log and hands it to the other handlers for processing
  |
  V
Other handlers format the message and output appropriately

If the queue handler was not in place, the program would have to wait until the end to continue. This would consume valuable time if you are waiting for HTTP calls to resolve.

Custom Discord Handler

Now we can get into some of the more fun stuff. Ieddit.com has a Discord server. Because of how the site is set up, only the creator had access to the error logs that were put out by the website.

The only logical remedy was to have the errors output to a Discord channel. So that is what we have done. Some set up is required for this. See the discord-webhook’s documentation to configure.

The above code creates a class that extends the logging.Handler class. When it is initialized, it sets its webhook URL based on the config file. Then, when a record is emitted, it gets forwarded on to Discord.

Using a File to Initialize Loggers

The last thing to do is create a file to initialize all of our loggers. Creating them before they are needed saves us from duplicating code. We can create and attach all our loggers in one place.# Logger Config.yaml
version: 1
objects:
 queue:
   class: queue.Queue
   maxsize: 1000
formatters:
 simple:
   format: '%(asctime)s - %(levelname)s - %(name)s - %(message)s'handlers:
 discord:
   class: utilities.log_utils.logger_util.DiscordHandler
   level: ERROR
   formatter: simple
 queue_listener:
   class: utilities.log_utils.logger_util.QueueListenerHandler
   handlers:
     - cfg://handlers.console
     - cfg://handlers.file
     - cfg://handlers.discord
   queue: cfg://objects.queueloggers:
 __main__:
   level: WARNING
   handlers:
     - queue_listener
   propagate: false
 ieddit:
   level: WARNING
   handlers:
     - queue_listener
   propagate: false

Here is what a sample config file looks like. Note, for things such as classes, we use the module name as it is defined.

Next, we can use a logger_init.py file to grab all these components and generate the loggers.# logger_init.py
import os
import config# Setup For Logging Init
import yaml
import logging
import utilities.log_utils.logger_util# Pull in Logging Config
with open('logger_config.yaml', 'r') as stream:
 try:
   logging_config = yaml.load(stream, Loader=yaml.SafeLoader)
 except yaml.YAMLError as exc:
   print("Error Loading Logger Config")
   pass# Load Logging configs
logging.config.dictConfig(logging_config)

With this fairly short bit of code, we can initialize all of the loggers and handlers that we want.

Then, to use them, we simply need to import the logger_init.py into our top-level file. Then, in all the others, we import logging and set our logger!# run.py
import logging
import logger_init # Only call at the top file inimport logginglogger = logging.getLogger("__main__")logger.warning("Woohoo I am Logging!")

To see this code in action check out ieddit.com’s GitHub page, where all the samples are being utilized.

Thanks for reading and stay tuned for more Python and programming content. Special thanks again to Rob Blackbourn for allowing me to use his code in this post.