Python Logging — A Comprehensive Guide

Why Do We Need Logging?

Logging is an invaluable tool for programmers. It offers insights into a program’s flow and reveals unforeseen scenarios during the development phase. It also serves as a continuous monitor checking the application’s flow. They record information such as user details or IP addresses accessing the application. In case of an error, logs offer insights beyond a stack trace, delineating the program’s state before the error occurred at a particular line of code.

Strategic logging of useful data aids in easy debugging of errors, performance analysis of the application for scaling plans, and comprehension of usage patterns for marketing strategy development. Python conveniently includes a logging system in its standard library, enabling quick integration of logging into your application. In this article, I will demonstrate why utilizing this module is the most effective way to introduce logging to your application.

Pic from clearsight

When to Use Loggging

From Python’s official documentation, you can determine when to use logging based on the following use cases:

Pic from Python doc

Python Logging Module

Python’s logging module is a robust, user-friendly tool designed to cater to the needs of both novice programmers and enterprise teams. This module introduces functions and classes that facilitate a versatile event logging system for applications and libraries.

The primary advantage of a logging API supplied by a standard library module is that it allows all Python modules to engage in logging. Given its widespread use across numerous third-party Python libraries, you can amalgamate your log messages with those from these libraries. This integration results in a unified log for your application.

To use logging module is simple, just import it into your code:

import logging

Once you’ve imported the logging module, it provides a feature known as a “logger,” which you can use to log messages that you wish to monitor. For example:

import logging

logging.info("This is an info message")
logging.warning("This is a warning message")

# Output
WARNING:root:This is a warning message

You may notice that the info message was not in the output, that is becuase by default, the logging module in Python is set to log messages with a severity level of WARNING or higher. This means that messages with severity levels of INFO or DEBUG won’t be displayed unless you configure the logging module to do so.

The severity levels in ascending order are DEBUG, INFO, WARNING, ERROR, and CRITICAL. In our case, the “This is an info message” isn’t printed because its level (INFO) is lower than the default level (WARNING).

To see the INFO messages, you need to set the logging level to INFO or lower. Here’s how:

import logging

logging.basicConfig(level=logging.INFO) 

logging.info("This is an info message") 
logging.warning("This is a warning message")

# Output
INFO:root:This is an info message
WARNING:root:This is a warning message

Also, the output displays the severity level preceding each message, accompanied by ‘root’, which is the name assigned to the default logger by the logging module. This format, which presents the level, name, and message separated by a colon (:), is the default output format. However, it can be configured to encompass additional details such as timestamp, line number, and more.

Logging Basic Configurations

The logging.basicConfig(**kwargs) function in Python is a simple way to configure the logging package for basic usage. It’s typically used to set up the formatting for how log messages will appear, where they will be outputted, and what level of messages to log.

Some common parameters that you can set with basicConfig:

• level: The root logger will be set to the specified severity level, which may be an integer or one of the DEBUG, INFO, WARNING, ERROR, and CRITICAL constants.
• filename: Specifies that a FileHandler be created, using the specified filename, rather than a StreamHandler.
• filemode: If filename is given, the file is opened in this mode. The default is a, which means ‘append’.
• format: This is the format of the log message.

Here is an example of how to use basicConfig to set the level to INFO and change the message format:

import logging

logging.basicConfig(level=logging.INFO, format='%(levelname)s: %(message)s')
logging.info("This is an info message")

# Output
INFO: This is an info message

Note, calling basicConfig does nothing if the root logger already has handlers configured. It is a convenience method intended for simple scripts, and for more sophisticated use cases, it’s recommended to directly configure handlers and formatters.

For example, consider the following code:

import logging

logging.error('This is an error message')
logging.basicConfig(level=logging.INFO)
logging.info('This is an info message')

In this case, the message ‘This is an error message’ triggers the creation of a default handler because logging has occurred before calling basicConfig. Therefore, basicConfig does nothing, and the ‘This is an info message’ will not be logged because the default level is WARNING.

Logging Output Format

However, just creating logs isn’t enough. Proper formatting of these logs is an essential aspect of effective log management.

Log formatting helps in enhancing the readability and understandability of the logs. It provides a consistent structure, making it easier to identify patterns or find specific information. Instead of having a wall of text, each log message can include specific pieces of data, each piece clearly separated and labeled.

Python’s logging module allows you to format log messages using a format string. The formatter allows placeholders in the log message format string, such as %(asctime)s for timestamp, %(levelname)s for log level, and %(message)s for the log message.

You can customize the formatting to include a wide range of information. Here are some commonly used format codes:

• %(name)s: Logger’s name.
• %(levelno)s: Numeric log level for the message.
• %(lineno)d: Source line number where the logging call was made.
• %(pathname)s: Full pathname of the source file where the logging call was made.
• %(filename)s: Filename portion of pathname.
• %(funcName)s: Function name where the logging call was made.

Here’s an example:

import logging

logging.basicConfig(format='%(asctime)s - %(levelname)s - %(message)s', level=logging.INFO)
logging.info("This is an info message")

# Output
2024-02-20 14:00:19,424 - INFO - This is an info message

or

import logging

logging.basicConfig(format='%(process)d-%(levelname)s-%(message)s')
logging.warning('This is a Warning')

# Output
21163-WARNING-This is a Warning

Advanced Formatting

For more advanced formatting needs, you can create subclass of logging.Formatter and override the format method to implement custom behavior.

For example:

class CustomFormatter(logging.Formatter):
    def format(self, record):
        # Customize the formatting
        pass

formatter = CustomFormatter()
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger = logging.getLogger(__name__)
logger.addHandler(handler)

Logging Dynamic Data

In many situations, you’ll want to incorporate dynamic information from your application into the logs. While the logging functions accept a string as an argument, and it might seem intuitive to format a string with variable data separately and then pass it to the log function, this can actually be achieved more directly.

You can use a format string for the message and append the variable data as arguments. This allows you to include dynamic, application-specific information directly in your log messages.

import logging

logging.basicConfig(level=logging.INFO)

username = 'test_user'
access_time = '11:45:23'

logging.info(f'User {username} accessed the system at {access_time}')

In this example, the variables username and access_time are included directly in the log message. The %s placeholders in the string are replaced with the subsequent arguments in the logging.info function call.

Logging Stack Traces

The logging module in Python also enables you to capture comprehensive stack traces in an application. You can capture exception information by passing exc_info as True when calling the logging functions. Here’s how you do it:

import logging

logging.basicConfig(level=logging.INFO)

try:
    1 / 0  # Division by zero
except Exception as e:
    logging.error('Exception occurred', exc_info=True)

Sample output:

ERROR:root:Exception occurred
Traceback (most recent call last):
  File "/mnt/efs/awside/data/home/lxu1/code/tony/python-code/log_test.py", line 6, in <module>
    1 / 0  # Division by zero
    ~~^~~
ZeroDivisionError: division by zero

This can be incredibly useful for debugging, as it provides you the complete context of where and why the error occurred.

Custom Logger

Up until now, we’ve discussed the use of the default logger, named ‘root’, which is employed by the logging module whenever its functions are invoked directly, such as with logging.debug(). However, for more complex scenarios, particularly when your application comprises multiple modules, it’s advisable to define your own logger.

You can do this by creating an object of the Logger class. This custom logger allows you to isolate and manage logging behaviors in different parts of your application independently. For instance, you might want more detailed logging (like DEBUG level logs) from a particular module while only wanting error level logs from another.

For example:

import logging

# Create a custom logger
logger = logging.getLogger('my_module')

# Set the level of this logger
logger.setLevel(logging.DEBUG)

# Create a custom handler
handler = logging.StreamHandler()

# Create a formatter and add it to the handler
formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# Add the handler to the logger
logger.addHandler(handler)

# Log some messages
logger.debug('This is a debug message')

In this example, a logger named ‘my_module’ is created, and its level is set to DEBUG. This configuration won’t affect the root logger or any other logger in your application. The ‘my_module’ logger will now generate DEBUG level logs, even if the root logger is set to a higher level like WARNING or ERROR.

Note, it’s generally advisable to utilize module-level loggers by passing __name__ as the name parameter to the getLogger() function when creating a logger object. The reason being, the name of the logger would indicate the source of the logged events. __name__ is a built-in variable in Python that corresponds to the name of the current module. Therefore, using __name__ facilitates tracking where the log entries originate from within your application.

Log Handlers

In Python’s logging module, a handler is an essential component that decides what happens to each log message in a logger. Once a log message is generated in a logger, it’s passed to its handlers, which are responsible for dispatching the appropriate log messages (based on their severity levels) to the handler’s specified destination.

Different types of handlers can send the log messages to a variety of output sinks, such as console (using StreamHandler), a rotating log file (using RotatingFileHandler), an HTTP server, or even an email server.

A logger can have multiple handlers, and each handler can have a different severity level. This means you can configure your logger to write debug messages to a file and error messages to the console, for example.

For example:

import logging

# Create a logger
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)  # Set logger level

# Create a console handler
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.WARNING)  # Set console handler level

# Create a file handler
file_handler = logging.FileHandler('app.log')
file_handler.setLevel(logging.DEBUG)  # Set file handler level

# Add the handlers to the logger
logger.addHandler(console_handler)
logger.addHandler(file_handler)

In this example, debug messages and above will be logged to the file ‘app.log’ because of the file handler, and warning messages and above will also be printed to the console because of the console handler.

Logging Configuration File

Setting up logging as illustrated above — using module and class functions — is primarily done within your application’s code. However, Python’s logging module also allows for configuration via a configuration file or a dictionary using fileConfig() or dictConfig() respectively. These methods provide the benefit of flexibility, especially if you want to change your logging configuration for an application that’s already running.

fileConfig()

This function reads a logging configuration from a section of a configuration file. In the file, you can define your loggers, handlers, formatters, and their configurations.

Example of a config file:

[loggers]
keys=root,sampleLogger

[handlers]
keys=consoleHandler

[formatters]
keys=sampleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_sampleLogger]
level=DEBUG
handlers=consoleHandler
qualname=sampleLogger
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=sampleFormatter
args=(sys.stdout,)

[formatter_sampleFormatter]
format=%(asctime)s [%(levelname)s] - %(message)s
datefmt=%m/%d/%Y %I:%M:%S %p

This file can be loaded using logging.config.fileConfig('logging.conf'). For example:

logging.config.fileConfig('logging.conf')
logger = logging.getLogger('sampleLogger')

dictConfig()

This function, on the other hand, takes a dictionary of configuration information. This can be particularly useful if your configuration is generated from other sources, like JSON or YAML files.

Example of dictConfig:

import logging.config

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': False,
    'loggers': {
        '': {  # root logger
            'level': 'DEBUG',
            'handlers': ['console'],
        },
        'my_module': {
            'level': 'ERROR',
            'handlers': ['console'],
            'propagate': False
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'basic',
        },
    },
    'formatters': {
        'basic': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s',
        },
    }
}

logging.config.dictConfig(LOGGING_CONFIG)

logger = logging.getLogger('my_module')
logger.error("This is an error message")

In this case, the configuration is defined as a Python dictionary and passed to logging.config.dictConfig().

Logging Best Practices

Create loggers using .getlogger()

The factory function logging.getLogger() in Python’s logging module helps manage the association between logger names and logger instances, and also maintains a hierarchy of loggers. This architecture provides several key benefits:

• Clients can use the factory function to access the same logger within various parts of the application by simply retrieving the logger via its name.
• During runtime, only a limited number of loggers are created under normal conditions.
• Log requests can be propagated upwards through the logger hierarchy.
• If not specified, a logger’s threshold logging level can be deduced from its ancestors.
• The logging library’s configuration can be updated during runtime by leveraging the logger names.

Use Module-Level Loggers

Use module-level loggers, and avoid using the root logger directly. This can help you manage the logging behavior of your application, or parts of it, independently.

logger = logging.getLogger(__name__)

Set Appropriate Logging Levels

Set appropriate logging levels for both loggers and handlers. Use DEBUG for detailed information, INFO for confirming normal operations, WARNING for indicating something unexpected occurred, ERROR when a problem prevents a function from completing, and CRITICAL for very serious errors.

Use Context-Specific Data

Use context-specific data within your log messages to provide more insight into issues. You can include data like variables or the state of the program in your log messages.

logger.error(f'An error occurred: {e}')

Avoid Logging Sensitive Information

Be careful not to log sensitive information such as passwords, user data, or any personally identifiable information (PII). This is important for security reasons and to comply with data privacy regulations.

Use RotatingFileHandler or TimedRotatingFileHandler for Log Files

If you’re writing logs to a file, it’s good practice to use RotatingFileHandler or TimedRotatingFileHandler to rotate log files when they get too large, otherwise, the log file will grow infinitely if your application runs long enough.

import logging
from logging.handlers import RotatingFileHandler

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

# create a file handler that logs even debug messages
fh = RotatingFileHandler('mylog.log', maxBytes=2000, backupCount=5)
fh.setLevel(logging.DEBUG)

# create a console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)

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

for i in range(10000):
    logger.info('Hello, world!')

In this example, the RotatingFileHandler is set up with a maxBytes of 2000, and backupCount of 5. This means that it will start a new log file whenever the current file exceeds 2000 bytes, and it will keep the last five files as backup.