Logging is a way to store information about your script and track events that occur. When writing any complex script in Python, logging is essential for debugging software as you develop it. Without logging, finding the source of a problem in your code may be extremely time consuming.

After completing this tutorial, you will know:

  • Why we would like to use the logging module
  • How to use the logging module
  • How to customize the logging mechanism

Let’s get started.

Logging in Python
Photo by ilaria88. Some rights reserved.

Tutorial Overview

This tutorial is divided into four parts; they are:

  • The benefits of logging
  • Basic logging
  • Advanced configuration to logging
  • An example of the use of logging

Benefits of Logging

You may ask: “Why not just use printing?”

When you run an algorithm and want to confirm it is doing what you expected, it is natural to add some print() statements at strategic locations to show the program’s state. Printing can help debug simpler scripts, but as your code gets more and more complex, printing lacks the flexibility and robustness that logging has.

With logging, you can pinpoint where a logging call came from, differentiate severity between messages, and write information to a file, which printing cannot do. For example, we can turn on and off the message from a particular module of a larger program. We can also increase or decrease the verbosity of the logging messages without changing a lot of code.

Basic Logging

Python has a built-in library, logging, for this purpose. It is simple to create a “logger” to log messages or information that you would like to see.

The logging system in Python operates under a hierarchical namespace and different levels of severity. The Python script can create a logger under a namespace, and every time a message is logged, the script must specify its severity. The logged message can go to different places depending on the handler we set up for the namespace. The most common handler is to simply print on the screen, like the ubiquitous print() function. When we start the program, we may register a new handler and set up the level of severity to which the handler will react.

There are 5 different logging levels that indicate the severity of the logs, shown in increasing severity:

  1. DEBUG
  2. INFO
  3. WARNING
  4. ERROR
  5. CRITICAL

A very simple example of logging is shown below, using the default logger or the root logger:

These will emit log messages of different severity. While there are five lines of logging, you may see only three lines of output if you run this script, as follows:

This is because the root logger, by default, only prints the log messages of a severity level of WARNING or above. However, using the root logger this way is not much different from using the print() function.

The settings for the root logger are not set in stone. We can configure the root logger to output to a particular file, change its default severity level, and format the output. Here’s an example:

Running this script will produce no output to the screen but will have the following in the newly created file file.log:

The call to logging.basicConfig() is to alter the root logger. In our example, we set the handler to output to a file instead of the screen, adjust the logging level such that all log messages of level DEBUG or above are handled, and also change the format of the log message output to include the time.

Note that now all five messages were output, so the default level that the root logger logs is now “DEBUG.” The log record attributes (such as %(asctime)s) that can be used to format the output can be found in the logging documentation.

Although there is a default logger, we usually want to make and use other loggers that can be configured separately. This is because we may want a different severity level or format for different loggers. A new logger can be created with:

Internally, the loggers are organized in a hierarchy. A logger created with:

will be a child logger created under the logger with the name “parent,” which, in turn, is under the root logger. Using a dot in the string signifies that the child logger is a child of the parent logger. In the above case, a logger with the name “parent.child” is created as well as one with the name "parent" implicitly.

Upon creation, a child logger has all the properties of its parent logger until reconfigured. We can demonstrate this with the following example:

This code snippet will output only one line:

which is created by the StreamHandler object with the customized format string. It happens only after we reconfigured the logger for parent because otherwise, the root logger’s configuration prevails, and no messages at level INFO will be printed.

Advanced Configuration to Logging

As we saw in the last example, we can configure the loggers we made.

Threshold of Level

Like the basic configuration of the root logger, we can also configure the output destination, severity level, and formatting of a logger. The following is how we can set the threshold of the level of a logger to INFO:

Now commands with severity level INFO and higher will be logged by the parent_logger. But if this is all you did, you will not see anything from parent_logger.info("messages") because there are no handlers assigned for this logger. In fact, there are no handlers for root logger as well unless you set up one with logging.basicConfig().

Log Handlers

We can configure the output destination of our logger with handlers. Handlers are responsible for sending the log messages to the correct destination. There are several types of handlers; the most common ones are StreamHandler and FileHandler. With StreamHandler, the logger will output to the terminal, while with FileHandler, the logger will output to a particular file.

Here’s an example of using StreamHandler to output logs to the terminal:

In the code above, there are two handlers created: A FileHandler created by logging.basicConfig() for the root logger and a StreamHandler created for the parent logger.

Note that even though there is a StreamHandler that sends the logs to the terminal, logs from the parent logger are still being sent to file.log since it is a child of the root logger, and the root logger’s handler is also active for the child’s log messages. We can see that the logs to the terminal include INFO level messages and above:

But the output to the terminal is not formatted, as we have not used a Formatter yet. The log to file.log, however, has a Formatter set up, and it will be like the following:

Alternatively, we can use FileHandler in the above example of parent_logger:

The example above demonstrated that you can also set the level of a handler. The level of parent_fhandler filters out logs that are not WARNING level or higher. However, if you set the handler’s level to DEBUG, that would be the same as not setting the level because DEBUG logs would already be filtered out by the logger’s level, which is INFO.

In this case, the output to parent.log is:

while that of file.log is the same as before. In summary, when a log message is recorded by a logger,

  1. The logger’s level will determine if the message is severe enough to be handled. If the logger’s level is not set, the level of its parent (and ultimately the root logger) will be used for this consideration.
  2. If the log message will be handled, all handlers ever added along the logger hierarchy up to the root logger will receive a copy of the message. Each handler’s level will determine if this particular handler should honor this message.

Formatters

To configure the format of the logger, we use a Formatter. It allows us to set the format of the log, similarly to how we did so in the root logger’s basicConfig(). This is how we can add a formatter to our handler:

First, we create a formatter, then set our handler to use that formatter. If we wanted to, we could make several different loggers, handlers, and formatters so that we could mix and match based on our preferences.

In this example, the parent.log will have:

and the file.log associated with the handler at root logger will have:

Below is the visualization of the flow of loggers, handlers, and formatters from the documentation of the logging module:

Flow chart of loggers and handlers in the logging module

An Example of the Use of Logging

Let’s consider the Nadam algorithm as an example:

The simplest use case is to use logging to replace the print() function. We can make the following change: First, create a logger with the name nadam before we run any code and assign a StreamHandler:

We must assign a handler because we never configured the root logger, and this would be the only handler ever created. Then, in the function nadam(), we re-create a logger nadam, but since it has already been set up, the level and handlers persisted. At the end of each outer for-loop in nadam(), we replaced the print() function with logger.info() so the message will be handled by the logging system:

If we are interested in the deeper mechanics of the Nadam algorithm, we may add more logs. The following is the complete code:

We prepared two level of loggers, nadam and nadam.iter, and set them in different levels. In the inner loop of nadam(), we use the child logger to print some internal variables. When you run this script, it will print the following:

Setting different loggers not only allows us to set a different level or handlers, but it also lets us differentiate where the log message comes from by looking at the logger’s name from the message printed.

In fact, one handy trick is to create a logging decorator and apply the decorator to some functions. We can keep track of every time that function is called. For example, we created a decorator below and applied it to the functions objective() and derivative():

Then we will see the following in the log:

where we can see the parameters and return values of each call to those two functions in the message logged by the nadam.function logger.

As we get more and more log messages, the terminal screen will become very busy. One way to make it easier to watch for issues is to highlight the logs in color with the colorama module. You need to have the module installed first:

Here’s an example of how you can use the colorama module with the logging module to change your log colors and text brightness:

From the terminal, you would see the following:

where the Fore, Back, and Style from the colorama module control the foreground, background, and brightness style of the text printed. This is leveraging the ANSI escape characters and works only on ANSI-supported terminals. Hence this is not suitable for logging to a text file.

In fact, we may derive the Formatter class with:

and use this instead of logging.Formatter. The following is how we can further modify the Nadam example to add color:

If we run it on a supporting terminal, we will see the following output:

Note that the colorful output can help us spot any abnormal behavior easier. Logging helps with debugging and also allows us to easily control how much detail we want to see by changing only a few lines of code.

Further Reading

This section provides more resources on the topic if you are looking to go deeper.

APIs

Articles

Summary

In this tutorial, you learned how to implement logging techniques in your scripts.

Specifically, you learned:

  • Basic and advanced logging techniques
  • How to apply logging to a script and the benefits of doing so