Use Python Logging Like a PRO: Don't be a Rookie

Table of Contents

Python Logging Module: An Overview

The Python Logging module is a fundamental component for tracking events in Python applications, providing a systematic way to collect and process log messages. It's an essential tool for debugging and monitoring Python code.

Modular Design of Python Logging:

Loggers in Python Logging: These are the primary elements of the Python Logging system. They capture log messages and pass them on for further handling.
Handlers in Python Logging: Handlers are responsible for dispatching the log messages to various destinations, such as files or the console, as defined in the Python Logging setup.
Filters in Python Logging: Filters offer a finer level of control, allowing selective processing of log messages based on specific criteria within the Python Logging framework.
Formatters in Python Logging: They define the layout of log messages, ensuring that the output is readable and informative.

Step-by-Step Example to use Python Logging

Follow the step by step instructions to configure and use Python logging:

1. Import the Logging Module:

Begin by importing the Python logging module:

import logging

2. Configure Logging:

Set up basic configuration for the logging system. This can be done using the basicConfig() function, where you can specify the logging level, output file, and message format.

logging.basicConfig(filename='example.log', level=logging.DEBUG, format='%(asctime)s:%(levelname)s:%(message)s')

3. Create a Logger Object:

Create a logger object that you will use to log messages.

logger = logging.getLogger(__name__)

4. Log Messages:

Use the logger to log messages at various severity levels: DEBUG, INFO, WARNING, ERROR, and CRITICAL.

logger.debug("This is a debug message")
logger.info("This is an info message")
logger.warning("This is a warning")
logger.error("This is an error message")
logger.critical("This is a critical message")

Understanding Python Loggers

Loggers are the core of the Python logging system. They are used to track events within an application. Events are logged via messages with varying levels of importance, such as DEBUG, INFO, WARNING, ERROR, and CRITICAL.

ALSO READ: The Ultimate Python Cheat Sheet for *args and **kwargs

To use a logger, you first need to import the logging module and then create a logger instance:

import logging
logger = logging.getLogger('my_logger')

Loggers have levels that determine the severity of messages they should capture. Setting a level filters out messages below that level:

logger.setLevel(logging.INFO)

Example-1: Single Module Usage

Suppose you have a simple Python script, simple_script.py:

# simple_script.py
import logging

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

logger.info("This is an informational message from simple_script")

When you run this script, it will output an info message tagged with the script's name (__name__ equals '__main__' in this case).

Example-2: Multiple Modules with Different Loggers

For better organization, especially in larger applications, you should use module-level loggers. Now, imagine you have a more complex application with two modules: module_a.py and module_b.py.

# module_a.py
import logging

logger = logging.getLogger(__name__)

def function_a():
    logger.info("Message from function_a in module_a")

# module_b.py
import logging
import module_a

logger = logging.getLogger(__name__)

def function_b():
    logger.info("Message from function_b in module_b")
    module_a.function_a()

if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO)
    function_b()

When you run module_b.py, it will output:

INFO:__main__:Message from function_b in module_b
INFO:module_a:Message from function_a in module_a

Here, you see the benefit of __name__. This is because when module_b.py is run as the main program, its __name__ attribute is set to '__main__' instead of 'module_b'. That's why the logger in module_b.py identifies itself as __main__ in the output. However, module_a.py is imported, so its __name__ attribute remains 'module_a', as reflected in the log message. This behavior underscores how Python's __name__ attribute works in differentiating between running a script directly versus importing it as a module.

Understanding Python Logging Handlers

Handlers in Python's logging framework are responsible for dispatching the log messages to various destinations like console, files, or even over the network. They work in conjunction with loggers to control where and how log messages are outputted.

Python offers several types of handlers, including:

1. StreamHandler

To send logging output to streams like the console (sys.stdout or sys.stderr).

import logging
import sys

logger = logging.getLogger('StreamLogger')
logger.setLevel(logging.DEBUG)

stream_handler = logging.StreamHandler(sys.stdout)
logger.addHandler(stream_handler)

logger.info("This message goes to the console")

2. FileHandler

ALSO READ: Pandas Pivot Simplified [In-Depth Tutorial]

To write log messages to a disk file.

logger = logging.getLogger('FileLogger')
logger.setLevel(logging.INFO)

file_handler = logging.FileHandler('logfile.log')
logger.addHandler(file_handler)

logger.info("This message is written to logfile.log")

3. RotatingFileHandler

To write log messages to a file, rotating the log file at a certain size.

from logging.handlers import RotatingFileHandler

logger = logging.getLogger('RotatingFileLogger')
logger.setLevel(logging.INFO)

rotating_handler = RotatingFileHandler('rotating.log', maxBytes=1024, backupCount=5)
logger.addHandler(rotating_handler)

logger.info("This message is written to a rotating log")

4. TimedRotatingFileHandler

To rotates log files at certain timed intervals.

from logging.handlers import TimedRotatingFileHandler

logger = logging.getLogger('TimedRotatingFileLogger')
logger.setLevel(logging.INFO)

timed_handler = TimedRotatingFileHandler('timed.log', when="midnight", interval=1, backupCount=3)
logger.addHandler(timed_handler)

logger.info("This message is written to a timed rotating log")

5. SocketHandler

To send log messages to a TCP/IP socket.

from logging.handlers import SocketHandler

logger = logging.getLogger('SocketLogger')
logger.setLevel(logging.INFO)

socket_handler = SocketHandler('localhost', 9090)
logger.addHandler(socket_handler)

logger.info("This message is sent over a TCP/IP socket")

6. HTTPHandler

Sends log messages to a web server using HTTP (GET or POST).

from logging.handlers import HTTPHandler

logger = logging.getLogger('HttpLogger')
logger.setLevel(logging.INFO)

http_handler = HTTPHandler('localhost:8000', '/log', method='POST')
logger.addHandler(http_handler)

logger.info("This message is sent to a web server via HTTP")

7. SMTPHandler

To email log messages.

from logging.handlers import SMTPHandler

logger = logging.getLogger('EmailLogger')
logger.setLevel(logging.ERROR)

smtp_handler = SMTPHandler(mailhost=("smtp.example.com", 587), fromaddr="me@example.com", toaddrs=["admin@example.com"], subject="Error Log")
smtp_handler.setLevel(logging.ERROR)
logger.addHandler(smtp_handler)

logger.error("This error message is sent via email")

8. NullHandler

A do-nothing handler, useful in libraries where loggers are defined but the configuration is left to the application using the library.

logger = logging.getLogger('NullLogger')
logger.addHandler(logging.NullHandler())

logger.info("This message goes nowhere")

Using Formatter to format log messages

Formatters are objects that configure the final order, structure, and contents of the log message. Unlike the basic string formatting used in basicConfig, formatters provide more control and can be used with different handlers to have distinct formats for different log destinations.

import logging

# Create logger
logger = logging.getLogger('my_logger')
logger.setLevel(logging.DEBUG)

# Create handler
file_handler = logging.FileHandler('myapp.log')

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

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

# Log messages
logger.info("This is an info message")

In this setup, the formatter specifies that each log message in myapp.log will include a timestamp, the logger's name, the level of the message, and the message itself.

Formatters in Python's logging module allow you to specify the exact format of your log messages. They use a string-based format where you can include various attributes. Some common options you can use in a formatter include:

%(asctime)s: The human-readable time when the LogRecord was created.
%(name)s: The name of the logger that created the record.
%(levelname)s: The textual logging level ('DEBUG', 'INFO', etc.).
%(message)s: The logged message.
%(pathname)s: The full pathname of the source file where the logging call was made.
%(filename)s: The filename portion of pathname.
%(module)s: The module name of the source file where the logging call was made.
%(funcName)s: The name of the function containing the logging call.
%(lineno)d: The line number in the source file where the logging call was made.
%(thread)d: The thread ID.

ALSO READ: Python copy list - deepcopy() vs copy() with examples

Example with Various Formatter Options:

import logging

# Create logger
logger = logging.getLogger('myapp')
logger.setLevel(logging.DEBUG)

# Create handler
stream_handler = logging.StreamHandler()

# Create formatter with multiple options
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - [%(filename)s:%(lineno)d] - %(message)s')

# Set formatter to handler
stream_handler.setFormatter(formatter)

# Add handler to logger
logger.addHandler(stream_handler)

# Log a message
logger.info("This is a test log message")

In this example, the formatter includes the timestamp, logger name, log level, source file name, line number, and the actual log message. This makes the log output detailed and informative, which is particularly useful for debugging and monitoring.

Using Filters in Python Logging

Filters in Python Logging provide a fine-grained mechanism for additional control over which log records are processed. They can be attached to loggers and handlers and are used to implement logging policies.

Example of Custom Filter:

import logging

# Custom filter class
class InfoFilter(logging.Filter):
    def filter(self, record):
        return record.levelno == logging.INFO

# Logger setup
logger = logging.getLogger('myLogger')
logger.setLevel(logging.DEBUG)

# Handler setup
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.DEBUG)

# Attach custom filter to handler
info_filter = InfoFilter()
stream_handler.addFilter(info_filter)

logger.addHandler(stream_handler)

# Test logging
logger.info("This is an info message.")
logger.debug("This debug message will not be printed.")

In this example, a custom filter InfoFilter is created to allow only INFO level messages. When attached to the stream_handler, it ensures that only messages with the INFO level are processed by that handler. The debug message in this case will not be displayed, demonstrating the filter's effect.

You might wonder, how Filters are different then defining LogLevels?

Filters in Python Logging offer more granular control than log levels. While log levels define a global threshold for logging severity, filters can impose additional, more complex criteria.

Using Log Levels

Log levels (DEBUG, INFO, etc.) are straightforward. A logger or handler with a set level will only process messages at that level or higher.

logger = logging.getLogger('myLogger')
logger.setLevel(logging.INFO)

# This message will be logged
logger.info("An info message")

# This message will NOT be logged
logger.debug("A debug message")

In this example, only messages at INFO level and above are logged.

Using Filters

Filters allow for custom rules, beyond the severity level.

class CustomFilter(logging.Filter):
    def filter(self, record):
        return "special" in record.getMessage()

logger.addFilter(CustomFilter())

# This message will NOT be logged, although it's INFO level
logger.info("An ordinary info message")

# This message will be logged because it meets the filter's condition
logger.info("A special info message")

Here, despite both messages being INFO level, only the one containing "special" is logged due to the filter's custom condition.

ALSO READ: Mastering Python Try Except Blocks [In-Depth Tutorial]

Configure Python Logging using basicConfig()

The basicConfig function in Python's logging module is used to configure the default settings of the logging system. It's a simple way to set up logging, especially useful for small scripts or quick setup.

1. Basic Console Logging:

import logging

logging.basicConfig(level=logging.INFO)
logging.info("This will get logged to the console")

2. Logging to a File:

logging.basicConfig(filename='example.log', level=logging.DEBUG)
logging.debug("This message will be logged to example.log")

3. Custom Log Format:

logging.basicConfig(format='%(levelname)s:%(message)s', level=logging.DEBUG)
logging.warning("This is a warning with a custom format")

4. Including Timestamps:

logging.basicConfig(format='%(asctime)s - %(message)s', level=logging.INFO, datefmt='%d-%b-%y %H:%M:%S')
logging.info("This log entry will have a timestamp")

Configure Python Logging using fileConfig()

fileConfig() is a function in Python's logging module that allows you to configure logging using a configuration file. This approach is beneficial for complex setups because it separates the logging configuration from the application code.

Key Features of fileConfig():

Separation of Configuration from Code: Keeps logging configuration in a separate file.
Ease of Maintenance: Allows updating logging settings without modifying the application code.
Flexibility: Supports various handlers, formatters, filters, and loggers.

The configuration file is typically in INI format with sections like [loggers], [handlers], [formatters], and [logger_loggername].

Logging Configuration File (logging_config.ini):

[loggers]
keys=root

[handlers]
keys=fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=fileHandler

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=simpleFormatter
args=('test.log', 'a')

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

Let us understand this file:

[loggers]: Lists the loggers to be configured. Typically, it includes the root logger and any additional custom loggers.
[handlers]: Specifies the handlers to be used. Handlers determine where the log messages are directed (e.g., console, file).
[formatters]: Defines the formatters, which determine the format of the log output.
[logger_*]: Each logger defined in [loggers] gets a section. Here, you specify the log level, handlers, etc., for that logger.
[handler_*]: Each handler defined in [handlers] gets a section. You define the class (e.g., StreamHandler, FileHandler), level, formatter, and other specific arguments here.
[formatter_*]: Each formatter defined in [formatters] gets a section. You specify the format of the log message here.

Here is another sample INI file:

[loggers]
keys=root,exampleLogger

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_exampleLogger]
level=DEBUG
handlers=fileHandler
qualname=exampleLogger
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=simpleFormatter
args=(sys.stdout,)

[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=simpleFormatter
args=('example.log', 'a')

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

In this example, there are two loggers (root and exampleLogger), two handlers (consoleHandler and fileHandler), and one formatter (simpleFormatter). The exampleLogger logs at DEBUG level to example.log, while the root logger logs at INFO level to the console. The format for log messages is specified in simpleFormatter.

Python Example:

import logging
import logging.config

logging.config.fileConfig('logging_config.ini')
logger = logging.getLogger(__name__)

logger.debug('This is a debug message')

In this setup, fileConfig('logging_config.ini') reads the logging configuration from logging_config.ini, which defines a file handler, a simple formatter, and sets the root logger's level to DEBUG. The Python code then gets a logger and logs a debug message. The log message is formatted and written to 'test.log' as per the configuration file.

ALSO READ: Best Practices for Python List Sorting: Tips & Tricks

How to add custom log levels

Adding custom log levels in Python logging involves a few steps: defining the new level, adding a method to both the logger and the logging module to handle it, and potentially configuring a formatter to display it properly.

1. Define the New Log Level:

import logging

VERBOSE_LEVEL_NUM = 15
logging.addLevelName(VERBOSE_LEVEL_NUM, "VERBOSE")

Add a Log Method for the New Level:

def verbose(self, message, *args, **kws):
    if self.isEnabledFor(VERBOSE_LEVEL_NUM):
        self._log(VERBOSE_LEVEL_NUM, message, args, **kws)

logging.Logger.verbose = verbose

Use the New Log Level:

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

logger.verbose("This is a verbose message")

Configure Formatter (Optional): If you're using a custom formatter, ensure it's set up to display the new log level.

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
stream_handler = logging.StreamHandler()
stream_handler.setFormatter(formatter)
logger.addHandler(stream_handler)

In this setup, the custom verbose messages will be logged with the VERBOSE level, providing more granularity in your logging setup.

Here's a complete example of how to define and use a custom log level in Python:

import logging

# Define a new log level
VERBOSE_LEVEL_NUM = 15
logging.addLevelName(VERBOSE_LEVEL_NUM, "VERBOSE")

# Create a new logging method for the level
def verbose(self, message, *args, **kws):
    if self.isEnabledFor(VERBOSE_LEVEL_NUM):
        self._log(VERBOSE_LEVEL_NUM, message, args, **kws)

logging.Logger.verbose = verbose

# Set up basic configuration and a simple formatter
logging.basicConfig(level=VERBOSE_LEVEL_NUM, format='%(asctime)s - %(levelname)s - %(message)s')

# Create a logger and use the custom level
logger = logging.getLogger(__name__)
logger.verbose("This is a verbose-level log message")

Output:

2023-11-12 00:14:46,482 - VERBOSE - This is a verbose-level log message

In this example, a new log level named "VERBOSE" is created and set lower than the standard INFO level. A new method verbose is added to the logger to handle this level. Finally, the logger uses this new level to log a message, demonstrating the custom log level in action.

Logging Uncaught Exceptions

Logging uncaught exceptions in Python is crucial for debugging and monitoring applications. It involves capturing exceptions that are not explicitly caught by try-except blocks.

Key Topics on Logging Uncaught Exceptions:

Using sys.excepthook: Override Python's default exception handling.
Creating a Custom Exception Handler: Define a function to log uncaught exceptions.
Integrating with the Logging System: Ensure that uncaught exceptions are logged with appropriate severity.

import logging
import sys

def handle_exception(exc_type, exc_value, exc_traceback):
    """
    Custom exception handler logging uncaught exceptions.
    """
    if issubclass(exc_type, KeyboardInterrupt):
        sys.__excepthook__(exc_type, exc_value, exc_traceback)
        return

    logger.error("Uncaught exception", exc_info=(exc_type, exc_value, exc_traceback))

logging.basicConfig(level=logging.ERROR)
logger = logging.getLogger(__name__)

# Override default excepthook
sys.excepthook = handle_exception

# Code that raises an uncaught exception
raise ValueError("This is an uncaught exception")

In this setup, handle_exception is a custom function that logs uncaught exceptions. It's set as the new sys.excepthook, which Python calls for unhandled exceptions. This way, exceptions that bubble up without being caught are logged. The KeyboardInterrupt is a special case to allow graceful exit on user interruption.

ALSO READ: Master Python Symmetric Difference: The Definitive Guide

Summary

Python logging is a versatile system that allows you to track events in your software, making it easier to understand what's happening, especially during debugging and monitoring. Key components include loggers, handlers, formatters, and filters. Loggers capture messages, handlers direct them to various destinations, formatters define message structure, and filters provide additional message control. Python also supports custom log levels and uncaught exception logging. The system's flexibility lies in its configurability for simple scripts to complex applications.

For comprehensive information and official documentation, visit:

Python Logging Overview: Python Logging Documentation
Advanced Tutorial: Logging Cookbook
Basic Tutorial: Logging HOWTO