How to Get Started with Logging in Python

Logging is an invaluable tool in every developer's toolbox when developing software. It provides a reliable means of recording and tracking events in the software and leaves an audit trail that captures the sequence of operations occurring within a system.

Developers use this audit trail to diagnose problems and understand program behavior at runtime — allowing them to react quickly to bugs discovered. This audit trail can also track user behavior, giving product teams and designers insight into the effectiveness of a design decision by analyzing user interactions with it.

In summary, logging allows different teams to understand the product by giving them insight into the program's or users' behavior. In this tutorial, we focus more on event logs that help you diagnose problems in your application. By reading through this article, you will gain an understanding of the following logging concepts in Python:

Prerequisites

Before we begin, you should have the latest Python version installed on your machine (v3.10 at the time of writing). If you are missing Python, you can find the installation instructions here.

To follow the examples provided in this article, clone the sample code repository to your computer and change into it:

git clone https://github.com/betterstack-community/python-logging

cd python-logging

Now that you are all set up, let's go ahead and explore the details of logging in Python!

Getting started with logging module

Python's built-in logging module is incredibly powerful and boasts the necessary logging features that one might require from a separate logging framework like pino for Node.js or Log4j for Java. Therefore, there is little competition in terms of third-party logging frameworks in the Python ecosystem.

By having the logging module in the standard library, all Python programs can benefit from having consistent logging features, making it easier to adopt and understand when inheriting another codebase.

import logging
print("Hello world")
logging.info("Logging INFO")
logging.warning("Logging WARNING")

You need to import the logging module into your program before you can use the methods defined on it. In the example above, we've imported the logging module, and we're using two of its methods: info() and warning().

Go ahead and execute the start.py program as shown below to see the logging module in action:

python start.py

Hello world
WARNING:root:Logging WARNING

Notice that "Logging WARNING" was printed to the console, but "Logging INFO" wasn't. This is due to the default log levels configured on the logging module which we will get to shortly. For now, know that this is the intended behavior of the above logging example.

Besides info() and warning(), there are other module-level functions for logging such as logging.debug(), logging.error(), and logging.critical(). With the basics of printing log messages in Python out of the way, let's discuss the various log levels available and how they should be used in your programs.

Understanding log levels

Log levels define the severity of an event when logging a message. Each log level has a corresponding module-level method in the logging module. For instance, when logging.info() is used, it logs messages at the INFO level, while logs produced by logging.warning() are at the WARNING level.

The available log levels in the logging module are as follows (ordered from least severe to most severe): DEBUG, INFO, WARNING, ERROR and CRITICAL. Each built-in level is also assigned a numeric value ranging from 10 to 50, with increments of 10 per level.

Log levels convey implicit meaning about the program state when the message was recorded, which is crucial when sieving through large logs for specific events. Generally, these are the meanings behind each log level:

1. DEBUG: used to give a detailed report about an event, especially when diagnosing problems.
2. INFO: something happened within the parameters of expected program behavior.
3. WARNING: something unexpected has occurred (which may impede future program function), but the program is still working as intended.
4. ERROR: the program has failed to perform a task due to an underlying issue. Often, an exception needs to be raised to avoid further failures, but the program may still be able to run.
5. CRITICAL: a severe error has occurred that can cause the program to stop running altogether. It should be used together with raising an exception to avoid further issues with the program.

Using the appropriate log level makes it easy to quickly find the information you need. For instance, logging with a level of ERROR or CRITICAL helps pinpoint bugs within the system that need to be rectified. If an inappropriate log level is used, these bugs might be missed and continue to plague the system.

By default, the logging module will only print messages for events that have a severity level of WARNING and above. This can be changed using logging.basicConfig() as demonstrated below:

import logging
logging.basicConfig(level="INFO") # level=logging.INFO works too
logging.info("This is an INFO")
logging.warning("This is a WARNING")

Ensure to place the call to logging.basicConfig() before any logging methods such as info(), warning(), and others. It should also be called once as it is a one-off configuration facility. If called multiple times, only the first one will have an effect.

When you execute the level.py program, you will observe the output below:

python level.py

INFO:root:This is an INFO
WARNING:root:This is a WARNING

Since we have set our minimum threshold to INFO, we are now able to view the log message produced by logging.info() and levels with a greater severity.

Formatting log messages

Beyond the log message itself, it is essential to include as much diagnostic information about the context surrounding an event in the log. Standardizing the structure of your logs entries makes it much easier to scan them and isolate only the necessary details.

Let's begin this section by exploring the structure of a good log entry, before we describe how you can get started with formatting log entries in Python.

A starting point for your log entries

Generally, a good log entry should at least include the following properties:

1. Timestamp: the time that the log was created.
2. Log level: the severity of the event.
3. Message: the details of the event.

These properties allow for filtering and deeper analysis by long-term log storage systems. You can ensure they are present in all your Python log entries by using the logging.basicConfig() method as shown below:

import logging
logging.basicConfig(format="%(levelname)s:%(asctime)s:%(message)s")
logging.warning("Something bad is going to happen")

The format argument above configures how log messages are displayed. It uses the following LogRecord attributes for formatting the logs:

• %(levelname)s: the log level text (INFO, DEBUG, WARNING, etc).
• %(asctime)s: human-readable time indicating when the log was created.
• %(message)s: the log message.

With the above configuration in place, all log entries produced by the logging module will now be formatted in the described manner.

python formatting.py

WARNING:2022-02-20 16:18:21, 479:Something bad is going to happen

Note that the numbers after the comma (479) refer to the timestamp's millisecond portion. Another good to have property would be the site of occurrence, which could be event's originating module or hierarchy of the modules. By default, the logging module defaults this location to root, but this is not too meaningful diagnostically, as we do not know the specific module or function where the event occurs.

We will discuss adding this bit of info later on. For now, understanding the structure of a good log helps us configure logging to enforce this structure across all logs within the program. Please refer to the LogRecord documentation to examine all the available attributes that you can use to format your log entries.

Adding custom attributes to your logs

Beyond the default LogRecord attributes, you can add custom attributes of your choosing to the format argument, then specify the value to interpolate into the formatting string in a logging method via the extra parameter.

import logging

logging.basicConfig(
    level=logging.INFO, format="%(asctime)s %(a)s %(b)s %(result)s :: %(message)s"
)


def exp(a, b):
    result = a
    for i in range(1, b + 1):
        logging.info("Iteration...", extra={"a": a, "b": b, "result": result})
        result *= a

    return result


exp(2, 3)

In the format string, three new attributes are defined for formatting: a, b, and result. These are custom attributes not present in the default LogRecord attributes, so we need to supply their values through the extra parameter at the log point.

python extra.py

2022-02-27 13:14:47,960 2 3 2 :: Iteration...
2022-02-27 13:14:47,960 2 3 4 :: Iteration...
2022-02-27 13:14:47,960 2 3 8 :: Iteration...

Note that if these attributes are not supplied at the log point, you will get an exception that looks like the following:

. . .
logging.info("Iteration...")
. . .

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib64/python3.10/logging/__init__.py", line 440, in format
    return self._format(record)
  File "/usr/lib64/python3.10/logging/__init__.py", line 436, in _format
    return self._fmt % values
KeyError: 'a'

In the next section, we will discuss why a good log message is important and dive into the specifics of a good log message should look like.

Writing good log messages

There are three major aspects to consider when writing log messages: when to log, what to log, and the contents of a log.

When to log

Logging is only useful when applied in the appropriate context. In general, you should log the significant events that occur during the execution of your program. This can range from events that occur during the normal operation of software to issuing warnings about runtime events that may pose future problems.

What to log

You can log just about anything within your program so long as it provides contextual clues and diagnostic benefits to understanding the runtime of a program or profiling the code. Generally, think about critical aspects of the program and log information that pertains to an issue you are facing.

It is also necessary to avoid logging sensitive information such as user credentials, API keys, secret tokens, or anything that can compromise user privacy or system security. Additionally, avoid recording information that may be a breach of business operations. This can include logging database transactions in plain text.

Contents of a log

A good log message should be informative to provide as much diagnostic information as possible. There is no point in logging something like "This works" since it does not provide much information about what "This" or "works" refers to.

For example, a good log message can look like this:

System is unable to use default port 80, attempting to use port 81

Notice that the message inherently reads as a non-urgent warning so it should be logged at the WARNING level. The log message should be intuitive — even if it stands alone with no other information. Another example of a good log message is as follows:

System has detected that the disk is almost full. This can cause unexpected data loss. Please run the "Disk cleanup" tool to remedy this

This message reads like a warning. It explains the problem, its implications, and the steps necessary to remedy it. While this log message might not be directly visible to end-users, the remedy might apply to you as the developer or system administrator.

A final example of a good log message can be:

System failed to parse input data file. Parse error caused by invalid character at line 139. Emojis cannot be parsed. Data file could not be loaded.

This message reads as an error, describing the problem in detail and implying that the program could not complete an operation as intended perhaps due to some invalid user input. End users might see a dialog with simplified instructions to remedy this issue.

Let's look at a few examples of bad log messages:

Something happened
Bad input
Crashed

These messages are unhelpful because they fail to provide contextual information about the event being logged. They also do not offer any remedies that the developer, user, or system has taken or can take to fix the issue. In the long run, having a list of log messages like these only serve to confuse those who read it and delay the debugging process significantly.

Adding contextual data to Python logs

Maximizing the contextual information available in a log entry increases the diagnostic use of the log. This usually involves describing the data being worked with when the event occurred so that enough information to replicate the issue and fix the problem can be gained just by reading through the logs.

The two main ways for maximizing the contextual information of log entries in Python's logging module are discussed below.

1. Overriding __str__

The __str__ method in Python is used to return the string representation of an object. We can define this method on a class to provide full contextual information about objects created from the class in a log entry. Here's an example that demonstrates this feature:

import logging

logging.basicConfig(level="INFO")


class UnformattedAnimal:
    def __init__(self, name, age, breed):
        self.name = name
        self.age = age
        self.breed = breed


class FormattedAnimal:
    def __init__(self, name, age, breed):
        self.name = name
        self.age = age
        self.breed = breed

    def __str__(self):
        return f"{self.name} is a {self.age} year old {self.breed}"


mochi_cat = UnformattedAnimal("Mochi", 4, "Cat")
logging.info("UnformattedAnimal: %s", mochi_cat)

sally_dog = FormattedAnimal("Sally", 14, "Dog")
logging.info("FormattedAnimal: %s", sally_dog)

python context.py

INFO:root:UnformattedAnimal: <__main__.UnformattedAnimal object at 0x7faec861ec80>
INFO:root:FormattedAnimal: Sally is a 14 year old Dog

As you can see, without defining a __str__ method, logging an object will print the traditional garble. When __str__ is defined on a class, key contextual information about objects produced from the class can be included in its string representation. This reduces the need to debug the program through breakpoints to analyze the properties of the object since it's already present in the log entry.

2. Adding stack traces to your logs

The logging.critical() method can be used to report errors without raising an exception. However, it is up to you to provide the necessary contextual information to understanding the issue. Failure to provide this information can reduce the visibility of the error as it might be difficult to trace where the problem occurred in the program.

To rectify this, we can use the exc_info parameter to add a stack trace alongside the error message.

import logging

try:
    a = 10 / 0
except Exception as exc:
    logging.critical("Critical error occurred")

try:
    a = 10 / 0
except Exception as exc:
    logging.critical("Critical error occurred", exc_info=True)

python stack_trace.py

CRITICAL:root:Critical error occurred
CRITICAL:root:Critical error occurred
Traceback (most recent call last):
  File "/home/chill/Projects/logging/stack_trace.py", line 9, in <module>
    a = 10 / 0
ZeroDivisionError: division by zero

As you can see, the first logging.critical() message does not really provide much context about the particular error that occurred. Such messages are unhelpful and can even be distracting when seeking out the cause of a problem. On the other hand, using exc_info printed the stack trace of the exception along with the log message which helps us easily pinpoint when the error occurred.

Although you can use logging.critical() to prevent a critical error from crashing the system by logging it instead, it is not advisable. Rather, you should log the crash details and throw the exception to prevent the program from causing further issues. Also, note that exc_info can only be used in exception contexts. If you need to log a stack trace without raising an exception, you can use the stack_info parameter instead:

import logging

logging.warning("A warning!", stack_info=True)

WARNING:root:A warning!
Stack (most recent call last):
  File "/home/chill/Projects/logging/main.py", line 3, in <module>
    logging.warning("A warning!", stack_info=True)

Now that we've discussed a few ways to add contextual information to our log entries, let's look at how we can save these logs into a file.

Saving logs to files

One of the most basic ways to store program logs for long term analysis is to save them to a file so that they are retained even when the terminal is closed or the system is rebooted. Support for saving Python logs to a file is built into the logging.basicConfig() method via the filename parameter:

import logging

logging.basicConfig(level='INFO', filename='result-2.log')
logging.info('This is an INFO')
logging.warning('This is a WARNING')
print('This is a regular message')

python file.py

This is a regular message

cat result-2.log

INFO:root:This is an INFO
WARNING:root:This is a WARNING

With this output, we can infer that print() calls are not affected by the configuration in logging.basicConfig(), and will continue to print to the console as the program is running unless redirected via the command shell. To ensure that the logs produced by all application modules are saved to a specific file, your logging configuration should be done in the entry file so that all imported modules will abide by the same rules.

import logging
import calculator

def main():
    logging.basicConfig(level='INFO', filename='main.log')
    logging.info('Starting application...')
    calculator.summation(1, 10)
    logging.info('Finished running')

if __name__ == '__main__':
    main()

import logging

def summation(start, end):
    logging.info('Starting summation with %i to %i', start, end)
    sum = 0
    for i in range(start, end + 1):
        sum += i

    logging.info('Summation is %i', sum)

    return sum

cd multi

python main.py

cat main.log

INFO:root:Starting application...
INFO:root:Starting summation with 1 to 10
INFO:root:Summation is 55
INFO:root:Finished running

As you can see, the logs produced by the calculator.py file also adhere to the configuration set in main.py. Notice that all the logs entries above are designated as originating from the root logger. This makes it difficult to pinpoint the origin module of a log entry. In the next section, we will discuss some features of the logging module that can help us solve this problem.

Setting up custom loggers

Using the module-level methods on the logging module (e.g. logging.info()) is a good way to get started with logging in Python. However, the module provides much more control over logs via several key classes:

1. Logger: exposes the interface that application code directly uses to write log entries.
2. LogRecord: a LogRecord represents a single log entry, and it contains everything pertaining to the event being logged.
3. Handler: sends the LogRecord objects (created by Logger) to the appropriate destination.
4. Formatter: specifies the layout of log records in the final output.
5. Filter: provides a facility for determining which logs are recorded to the configured destination.

Essentially, objects of the Logger class can be used to replace the root logger, by virtue of having all the necessary logging methods like info() and warning(), while the other four classes provide configuration for the Logger instance. We will mostly consider the Logger, Handler, and Formatter classes in this section.

Every Logger is instantiated with a name, which can be tied to the originating module. Alternatively, it can also adopt a naming convention such as <project>.<module>, making it easy to trace a log entry to its originating project and module.

A Handler can be instantiated and added to a Logger to send the logs to a given destination, including the console, file, network socket, UDP socket, etc. There are several types of Handler objects, each with a preconfigured destination. For example, StreamHandler sends logs to the console while FileHandler sends logs to a given file.

You can also configure several Handlers on a given Logger instance. For example, a Logger can be configured so that logs with a severity of WARNING and above are printed to the console, while INFO and above are placed in a file.

The Formatter, on the other hand, determines the format of the log entries produced by a Logger. By default, a Logger will not have a specific format, so all it will output is the log message.

Let's take a look at the following code snippets to see these three classes in action:

import logging
import calculator

logger = logging.getLogger('advanced.main')
logger.setLevel(logging.INFO)

# Create console handler for INFO and up, any other messages should be handled by the individual modules
ch = logging.StreamHandler()
ch.setLevel(logging.INFO)

logger.addHandler(ch)

def main():
    logger.info('Starting advanced')
    sum = calculator.summation(1, 15)
    logger.info('Summation returned %i', sum)
    calculator.divide(sum, 3)
    calculator.divide(sum, 0)
    logger.info('Finished...')

if __name__ == '__main__':
    main()

import logging

logger = logging.getLogger('advanced.calculator')
logger.setLevel(logging.INFO)

# Create a console handler to print logs with WARNING and up
ch = logging.StreamHandler()
ch.setLevel(logging.WARNING)

# Create a console handler to print logs with INFO and up
fh = logging.FileHandler('advanced.log')
fh.setLevel(logging.INFO)

logger.addHandler(ch)
logger.addHandler(fh)

def summation(start, end):
    logger.info('Starting summation')
    sum = 0
    for i in range(start, end + 1):
        logger.info('Summing %i with %i', i, sum)
        sum += i

    logger.info('Total sum from %i to %i is %i', start, end, sum)

    return sum

def divide(a, b):
    logger.info('Dividing %i by %i', a, b)
    try:
        result = a / b
    except Exception as exc:
        logger.error('Error occurred with dividing', exc_info=True)

In the above snippets, we have two modules: main and calculator, each with their respective Logger instance. Each logger is created by calling getLogger() on the logging module. As you can see, the name passed to this method is of the format: <project>.<module>.

In the main module, we added a StreamHandler() to the Logger which causes the log messages to be sent to the standard error stream by default. If you want to log to the standard output instead, specify the following to the StreamHandler constructor:

import sys
# ...
ch = logging.StreamHandler(sys.stdout)

In the calculator module, we've configured the handlers such that entries with WARNING severity and up are printed to the standard error while INFO and up are saved to a file called advanced.log. We also formatted the logs are being recorded to the advanced.log file alone so that the logs printed to the console only display the message.

python main.py # Prints only the logger.info() calls from `main` and logger.warning() from `calculator`

Starting advanced
Summation returned 120
Error occurred with dividing
Traceback (most recent call last):
  File "/home/chill/Projects/logging/advanced/calculator.py", line 31, in divide
    result = a / b
ZeroDivisionError: division by zero
Finished...

cat advanced.log # Prints every log message from calculator but not from main

2022-02-25 20:07:57,856 - advanced.calculator - INFO - Starting summation
2022-02-25 20:07:57,856 - advanced.calculator - INFO - Summing 1 with 0
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 2 with 1
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 3 with 3
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 4 with 6
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 5 with 10
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 6 with 15
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 7 with 21
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 8 with 28
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 9 with 36
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 10 with 45
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 11 with 55
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 12 with 66
2022-02-25 20:07:57,857 - advanced.calculator - INFO - Summing 13 with 78
2022-02-25 20:07:57,858 - advanced.calculator - INFO - Summing 14 with 91
2022-02-25 20:07:57,858 - advanced.calculator - INFO - Summing 15 with 105
2022-02-25 20:07:57,858 - advanced.calculator - INFO - Total sum from 1 to 15 is 120
2022-02-25 20:07:57,858 - advanced.calculator - INFO - Dividing 120 by 3
2022-02-25 20:07:57,858 - advanced.calculator - INFO - Dividing 120 by 0
2022-02-25 20:07:57,858 - advanced.calculator - ERROR - Error occurred with dividing
Traceback (most recent call last):
  File "/home/chill/Projects/logging/advanced/calculator.py", line 34, in divide
    result = a / b
ZeroDivisionError: division by zero

As you can see, using these classes provides fine-grained control over what is logged, how it is logged, and where it is logged. This also makes it possible to have different settings in different modules, and helps with avoiding the problem of over-logging as it ensures that only the pertinent logs are left in the appropriate mediums.

Aggregating Logs

Log aggregation involves consolidating all application logs into a single centralized platform. A log management system allows log records to be filtered for debugging, and analyzed to provide insights into the program's operation. This is especially useful when managing an application that is deployed to multiple servers.

Several log aggregation tools commonly used in production systems include Logtail, SolarWinds Papertrail, Logstash, and FluentD.. These solutions handle the storage, analysis, and visualization of logs, alleviating the need to set everything up yourself.

We will briefly demonstrate how a log aggregation system works with Logtail. Logtail is chosen here for its ability to work seamlessly with the existing logging system in Python. To get started, set up a free Logtail account and create a new source for Python to obtain a source token. We will be referencing the calculator example from the previous section.

Go ahead and install the Logtail library for Python as shown below:

pip install logtail-python

Afterward, add a new Handler to the logger by modifying calculator.py below. This causes all the logs produced by this logger to be routed to Logtail.

import logging
from logtail import LogtailHandler

logger = logging.getLogger('advanced.calculator')
logger.setLevel(logging.INFO)

# Create a Logtail handler
lh = LogtailHandler(source_token='<source_token>')

logger.addHandler(lh)
. . .

Make sure you replace the <source_token> placeholder with your Logtail source token.

After running the application, you can view a stream of incoming log entries in the Live tail section of the dashboard. You should observe something similar to the screenshot below:

This process is exemplified in the aggregate/ directory so feel free to reference the code there to understand how Logtail was setup.

Conclusion

Logging is a double-edged sword. While it can enhance the diagnostic process when debugging or improve one's understanding of a program's behavior, failure to design and maintain high quality logs can work against these goals.

This article provides a launchpad for you to understand what logging is all about, how to implement it in Python, the key characteristics of a good log entry, and how it can be enhanced using a log management tool like Logtail.

If you are interested to learn more about the intricacies of logging in Python, we highly recommend perusing the official logging module documentation. Thanks for reading, and happy logging!

This article was contributed by guest author Woo Jia Hao, a Software Developer from Singapore! He is an avid learner who loves solving and talking about complex and interesting problems. Lately, he has been working with Go and Elixir!

Article by

Woo Jia Hao

Woo Jia Hao is a software developer from Singapore. He is an avid learner who loves solving and talking about complex and interesting problems. Lately, he has been working with Go and Elixir!

Got an article suggestion? Let us know

Next article

A Complete Guide to Logging in Python with Loguru

Learn how to install, configure, and use the Loguru framework for logging in Python applications

→

This work is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.