Python Logging

Logging is a crucial aspect of software development that helps developers track events, debug issues, and monitor application health. Python's built-in logging module provides a flexible framework for emitting log messages from your applications. In this guide, we'll explore how to implement effective logging in your Python projects.

Introduction to Python Logging

When developing applications, especially those running in production environments, it's essential to have visibility into what's happening within your code. While print() statements might work for simple debugging during development, a proper logging system offers several advantages:

• Different severity levels for messages (debug, info, warning, error, critical)
• Configurable output destinations (console, files, network services)
• Structured formatting of log messages
• Filter capabilities based on importance or module
• Thread safety for concurrent applications

Python's logging module is part of the standard library and follows best practices for application logging.

Getting Started with Basic Logging

Let's start with the simplest example of using the logging module:

python

import logging

# Log a simple message
logging.warning("This is a warning message")

Output:

WARNING:root:This is a warning message

By default, the logging module displays messages with severity level WARNING and above. The five standard logging levels in order of increasing severity are:

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

To log at different levels:

python

import logging

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

Output:

WARNING:root:This is a warning message
ERROR:root:This is an error message
CRITICAL:root:This is a critical message

Notice that DEBUG and INFO messages don't appear by default. To change this, you need to configure the logging level:

python

import logging

# Set the logging level to INFO
logging.basicConfig(level=logging.INFO)

logging.debug("This is a debug message")
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

Configuring Logging Format

The default log format may not provide all the information you need. You can customize the format using the basicConfig() function:

python

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s'
)

logging.debug("Debug message with timestamp")

Output:

2023-07-14 15:30:42,123 - root - DEBUG - Debug message with timestamp

Common format specifiers include:

• %(asctime)s: Human-readable date/time
• %(name)s: Logger name
• %(levelname)s: Level (DEBUG, INFO, etc.)
• %(message)s: The actual log message
• %(filename)s: Source filename
• %(funcName)s: Function name
• %(lineno)d: Line number
• %(process)d: Process ID
• %(threadName)s: Thread name

Logging to Files

To save logs to a file instead of (or in addition to) displaying them in the console:

python

import logging

# Configure logging to write to a file
logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    filename='app.log',
    filemode='w'  # 'w' to overwrite, 'a' to append
)

logging.debug("This message will be written to the file")
logging.info("Application started")

This will create an app.log file in your working directory with the log messages.

Creating and Using Logger Objects

For larger applications, it's better to create specific loggers rather than using the root logger:

python

import logging

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

# Set level for this logger
logger.setLevel(logging.DEBUG)

# Create handlers
c_handler = logging.StreamHandler()  # Console handler
f_handler = logging.FileHandler('app.log')  # File handler

# Set levels for handlers
c_handler.setLevel(logging.WARNING)
f_handler.setLevel(logging.ERROR)

# Create formatters and add to handlers
c_format = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
f_format = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
c_handler.setFormatter(c_format)
f_handler.setFormatter(f_format)

# Add handlers to the logger
logger.addHandler(c_handler)
logger.addHandler(f_handler)

# Use the logger
logger.warning('This is a warning')
logger.error('This is an error')

Output in console:

my_app - WARNING - This is a warning
my_app - ERROR - This is an error

Output in file (app.log):

2023-07-14 15:35:23,456 - my_app - ERROR - This is an error

Logging in Multiple Modules

In larger applications with multiple modules, you should create loggers based on the module name. This creates a hierarchical structure of loggers:

File: main.py:

python

import logging
import helper

# Configure root logger
logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s'
)

# Create logger for this module
logger = logging.getLogger(__name__)

logger.info("Main module started")
helper.do_something()
logger.info("Main module finished")

File: helper.py:

python

import logging

# Create logger for this module
logger = logging.getLogger(__name__)

def do_something():
    logger.info("Helper function called")
    try:
        result = 10 / 0
    except Exception as e:
        logger.error(f"Error in helper function: {e}")

Output:

2023-07-14 15:40:12,789 - __main__ - INFO - Main module started
2023-07-14 15:40:12,790 - helper - INFO - Helper function called
2023-07-14 15:40:12,791 - helper - ERROR - Error in helper function: division by zero
2023-07-14 15:40:12,792 - __main__ - INFO - Main module finished

Real-World Application: Web Server Logging

Let's create a more practical example with Flask (a popular Python web framework):

python

import logging
from flask import Flask, request

# Configure logging
logging.basicConfig(
    level=logging.INFO,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
    filename='webapp.log',
    filemode='a'
)

# Create logger
logger = logging.getLogger('webapp')

# Create Flask app
app = Flask(__name__)

@app.before_request
def log_request_info():
    logger.info(f'Request: {request.method} {request.path} from {request.remote_addr}')

@app.route('/')
def home():
    logger.info('Home page accessed')
    return 'Welcome to the homepage!'

@app.route('/api/data')
def get_data():
    try:
        # Simulate error
        if request.args.get('error') == 'true':
            raise ValueError("Requested error triggered")
        
        logger.info('Data retrieved successfully')
        return {"status": "success", "data": [1, 2, 3]}
    except Exception as e:
        logger.error(f'Error retrieving data: {str(e)}')
        return {"status": "error", "message": str(e)}, 500

if __name__ == '__main__':
    logger.info('Starting web application')
    app.run(debug=True)
    logger.info('Web application stopped')

This example demonstrates how logging can be used in a web application to:

1. Record when the application starts and stops
2. Log incoming requests with details
3. Track specific route access
4. Record errors with proper context

Logging Configuration Using Dictionary

For more advanced applications, you might want to configure logging using a dictionary:

python

import logging
import logging.config

# Define the logging configuration
config = {
    'version': 1,
    'formatters': {
        'standard': {
            'format': '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
        },
        'simple': {
            'format': '%(levelname)s - %(message)s'
        },
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'level': 'INFO',
            'formatter': 'simple',
            'stream': 'ext://sys.stdout'
        },
        'file': {
            'class': 'logging.FileHandler',
            'level': 'DEBUG',
            'formatter': 'standard',
            'filename': 'app_detailed.log',
            'mode': 'a',
        }
    },
    'loggers': {
        '': {  # root logger
            'handlers': ['console', 'file'],
            'level': 'DEBUG',
            'propagate': True
        },
        'api': {
            'handlers': ['file'],
            'level': 'DEBUG',
            'propagate': False
        }
    }
}

# Apply the configuration
logging.config.dictConfig(config)

# Use the loggers
root_logger = logging.getLogger()
api_logger = logging.getLogger('api')

root_logger.info("This is the root logger")
api_logger.debug("This is the API logger")

This configuration approach allows for more flexibility and is often used in production applications.

Rotating Log Files

For long-running applications, your log files might become too large. The RotatingFileHandler helps manage file size:

python

import logging
from logging.handlers import RotatingFileHandler

# Create logger
logger = logging.getLogger('app')
logger.setLevel(logging.INFO)

# Create handler
# Max size of 5MB, keep 3 backup files
handler = RotatingFileHandler(
    'app.log', 
    maxBytes=5*1024*1024,  # 5MB
    backupCount=3
)
handler.setLevel(logging.INFO)

# Create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# Add handler to logger
logger.addHandler(handler)

# Log messages
for i in range(1000000):
    logger.info(f"Log message {i}: This is a test message")

This will create app.log and, when it reaches 5MB, rotate it to app.log.1 and create a new app.log. If you already have backups, they'll be renamed (e.g., app.log.1 becomes app.log.2).

Capturing Stack Traces

When logging exceptions, it's useful to capture the full stack trace:

python

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format='%(asctime)s - %(name)s - %(levelname)s - %(message)s'
)

logger = logging.getLogger(__name__)

def divide(x, y):
    try:
        result = x / y
        logger.info(f"Division result: {result}")
        return result
    except Exception as e:
        logger.error("Exception occurred", exc_info=True)
        # Or alternatively:
        # logger.exception("Exception occurred")  # automatically adds stack trace

divide(10, 0)

Output:

2023-07-14 16:05:23,456 - __main__ - ERROR - Exception occurred
Traceback (most recent call last):
  File "example.py", line 15, in divide
    result = x / y
ZeroDivisionError: division by zero

Summary

Python's logging module provides a robust framework for adding logging to your applications. Key takeaways include:

1. Use the appropriate log level (DEBUG, INFO, WARNING, ERROR, CRITICAL) based on message importance
2. Configure logging early in your application
3. Create specific loggers for different modules
4. Format log messages to include relevant context
5. Use file handlers for persistent logs
6. Consider rotating logs for long-running applications
7. Always log exceptions with stack traces

Proper logging practices will help you debug issues, monitor application health, and understand user behavior in production environments.

Additional Resources

• Python Official Documentation - Logging Module
• Python Logging Cookbook
• Real Python - Logging in Python

Exercises

1. Create a simple script that logs messages at different severity levels to both console and file.
2. Modify the logging format to include the line number and function name.
3. Implement a rotating log system that creates a new log file each day.
4. Create a multi-module application with hierarchical loggers.
5. Create a logging configuration that sends critical errors to your email (hint: look up SMTPHandler).

By mastering Python logging, you'll be better equipped to build robust, maintainable, and observable applications - a critical skill for any DevOps practitioner or Python developer.