Python Logging Basics

Introduction

Logging helps you keep track of events happening during the execution of your code, which can then be used in the future for debugging purposes. It provides a better picture of the flow of the application and helps developers trace the source of errors that happens during execution of your code, thereby enhancing the maintainability of the application.

In Python, most of the basic logging features are provided by the Python standard library. Hence, you can add logging to your application easily without any extra configurations. The standard logging module enables the developer to write status messages to a file or any other output stream.

The logging Module

The logging module is readily available in Python environments by default and provides a default logger named "root". It defines the functions and classes that implement logging functionality.

The logging API provided by the standard library enables you to include your own messages in the application log, as well as integration with messages from third-party modules. It also provides a mechanism to annotate the log messages with the source, timestamp, severity and other metadata, which helps in log analysis.

Logging Types (Log levels)

Each log message is associated with a severity level, which is an integer used to signal the criticality of the event(s) logged. The logging module has a helper function for each log level - these are named according to the log level. Below, is a list of logging levels along with their recommended usage.

• Debug (logger.debug): Provide very detailed output. Used for diagnosing problems.

• Info (logger.info): Provides information on successful execution. Confirms if things are working as expected.

• Warning (logger.warn or logger.warning): Issue a warning regarding a problem that might occur in the future or a recoverable fault.

• Error (logger.error): Indicates a problem in the software as it is not executing as expected.

• Critical (logger.critical): Indicates a serious error that might stop the program from running.

By default, the root logger is set up to report all messages at or above the Warning level - any messages below this level are filtered. However, it is possible to configure the module explicitly to be more or less selective in filtering.

To add logging to a Python script, just import the module using import logging, and after a successful import the script can log messages using the logging.* methods, such as logging.debug().

Here you can see a simple example of the logging module in action:

import logging
logging.warning("Caution: This is the root logger!")

Output:

WARNING:root:Caution: This is the root logger!

Logger Objects

The logging module allows the user to create multiple logger objects. Different types of logger objects can be used to obtain fine-grained control over how different parts of a Python application log their messages - for example, the main Python app can use the root logger whereas the third-party libraries used from within this app can use their own logger objects with their own configurations.

While using the default root logger's functions, we can call the functions directly, e.g., logging.debug(). It is possible to configure your own logger by creating an object of the Logger class, and this can be useful if your application has multiple modules.

Let's have a look at some of the classes and functions in the logging module. The basic classes and their functions are as follows:

• Loggers – Exposes the interface that the app uses. The objects of this class are used directly to call the functions in the application.

• Handlers – Sends log messages to the appropriate location in the software like standard output console, a file, via HTTP, or even email (via SMTP).

• Filters – Gives fine-grained control over the choice of log records to display.

• Formatters – Specifies the final layout of log records, specifying the attributes the output must contain.

Of these, the objects of the Logger class are used most frequently.

To create a new logger, we can use the logging.getLogger() method. In the following script, we log errors using the root logger as well as our custom logger my_logger.

import logging

my_logger = logging.getLogger("My Logger")
logging.error("Error: Root Log")
my_logger.error("Error: My Logger log")

Output:

ERROR:root:Error: Root Log
ERROR:My Logger:Error: My Logger log

Each log message will not only indicate the source - the logger object through which it was logged - but will display a message based on the configuration of that logger object.

In the following sections, we will look at the various configuration options of logger objects.

Logging to a File vs the Standard Output

By default logger objects output the logs to the standard output. You can use the basicConfig() method to change this and other parameters. Below is a list of parameters for the basicConfig method:

• level: Set a severity level for the logger. Any messages below this severity level will not be logged.
• filename: The name of the file where logs are written.
• filemode: The mode in which the file specified, if any, is to be opened.
• format: Specifies the format of the log message. This is a string with LogRecord attributes.

LogRecord object contains the information of the events that are logged, like the line number, time, name of the logger, etc. Discussing the LogRecord object is outside the scope of this article but more information is available here.

Below is a summary of the steps to be followed to record log events to a file:

1. Import the logging module.
2. Configure the logger using basicConfig method
3. Creating a logger object.
4. Setting the threshold value of logger.
5. Use the logging methods.

This can be better understood by an example:

# Filename: test_logger.py

import logging

# Create a logger object
logger = logging.getLogger()

# Configure logger
logging.basicConfig(filename="test.log", format='%(filename)s: %(message)s', filemode='w')

# Setting threshold level
logger.setLevel(logging.DEBUG)

# Use the logging methods
logger.debug("This is a debug message")
logger.info("For your info")
logger.warning("This is a warning message")
logger.error("This is an error message")
logger.critical("This is a critical message")

The script above will create a file test.log. The file will contain the following logging information:

test_logger.py: This is a debug message
test_logger.py: For your info
test_logger.py: This is a warning message
test_logger.py: This is an error message
test_logger.py: This is a critical message

Date/Time in Log Messages

To display the date and time of the occurrence of an event, you can use %(asctime)s in your format string in the basicConfig() function. For example:

import logging

logging.basicConfig(format='%(asctime)s %(message)s')
logging.warning('is the time the Admin logged out.')

Output:

2018-12-17 10:52:15,463 is the time the Admin logged out.

If you want to change the way the date/time shows up, you can configure it using the datefmt parameter of the basicConfig method.

Logging Variables

In real-world applications, we need to output logs according to the dynamic changes happening in our application. As seen in the above example, logging methods take a string as an argument. In addition, we can include variables and format the string with placeholders and then pass it to the log method. At run-time, the value of the variables will be output in the log messages.

Here's an example of that using string formatting:

import logging

status = "connection unavailable"
logging.error("System reported: %s", status)

Output:

ERROR:root:System reported: connection unavailable

Starting with Python 3.6 f-Strings can be used as an alternative to string format specifiers, thereby keeping the code easily readable when there are multiple parameters. Using f-strings you can specify any Python expression as part of the message and these are evaluated during run-time and the result will be embedded into the log messages.

The above example can be re-written using an f-string as:

import logging

status = "connection unavailable"
logging.error(f'System reported: {status}')

Logging Stack Traces

Capturing stack traces in your application is also supported by the logging module. Setting the exc_info parameter to True while calling the logging functions allows us to capture the exception information. By using this function, we can get information about the exception that is currently being handled. The information is specific to the current thread and the current stack frame.

import logging

my_list = [1, 2]
try:
    print(my_list[3]) # Index out of range
except Exception as e:
    logging.error("Caught Exception!", exc_info=True)

Output:

ERROR:root:Caught Exception!
Traceback (most recent call last):
  File "index.py", line 5, in <module>
    print(my_list[3]) # Index out of range
IndexError: list index out of range

In case exceptions are not handled by the current stack frame, the information is then obtained from its caller (i.e. the calling stack frame) and so on until it finds a stack frame to handle the exception. The stack frame has the information of the most recently handled exception.

If the stack has no exceptions being handled, a tuple having None value is returned. Otherwise the function returns value of type (the type of exception that is handled), value (exception parameter) and traceback (the traceback object which encapsulates the call stack where the exception occurred originally).

Conclusion

The design of the logging module is very practical, providing ready-to-use logging features that can add basic logging to a small project. It can be easily extended by using logger objects and their rich configuration options to support the needs of even the most demanding of applications. In addition to messages, the logging module can also be used to log exceptions and stack traces. This concludes the basic tutorial on implementing logging in Python.