Python logging 설정 및 활용

Introduction

Every serious application needs proper logging, yet many Python developers either skip it entirely or use print() statements that are useless in production. Python's logging module is powerful but has a confusing API that leads many developers to either over-configure or under-configure it.

I learned this lesson the hard way when a production trading bot in Lisbon started executing trades at wrong prices. Without proper logging, I had no way to trace what went wrong. The print() statements I had added during development were lost in the noise of Docker container logs.

Environment

Python 3.12.3

Problem

Problem 1: print() is not logging

# This is what many developers do
def process_order(order):
    print(f"Processing order: {order}")
    if order["amount"] > 1000:
        print("WARNING: Large order!")
    result = execute_trade(order)
    print(f"Result: {result}")
    return result

In production, these prints go to stdout, are not timestamped, have no log level, and cannot be filtered.

Problem 2: Basic config is too limited

import logging
logging.basicConfig(level=logging.INFO)

logger = logging.getLogger(__name__)
logger.info("Starting application")  # Works but no file output

Problem 3: Module-level logging confusion

# logger.py
import logging
logger = logging.getLogger(__name__)

# main.py
import logging
logging.basicConfig(level=logging.DEBUG)
import logger  # logger's level may not change
logger.logger.info("This might not appear")  # Confusing!

Problem 4: Logging in multiple modules creates duplicates

# module_a.py
import logging
logger = logging.getLogger(__name__)
logger.addHandler(logging.FileHandler("app.log"))

# module_b.py
import logging
logger = logging.getLogger(__name__)
logger.addHandler(logging.FileHandler("app.log"))

# Now every message appears twice in app.log

Analysis

The confusion stems from Python's logging hierarchy. Loggers are organized in a tree structure with the root logger at the top. When you call logging.basicConfig(), you are configuring the root logger. Module loggers propagate messages up to the root logger by default.

Why print() is not enough:

• No timestamps
• No log levels for filtering
• No structured output
• No file rotation
• No way to enable/disable in different environments

Why basicConfig() is limited:

• Only configures the root logger
• Cannot set different formats for console vs file
• No rotation or compression
• No structured (JSON) output

Why duplicate logging happens:

When a logger has no handlers, it propagates to its parent. If you add a handler to a child logger AND the root logger has a handler, messages appear twice.

Solution

Fix 1: Centralized logging configuration

# logging_config.py
import logging
import sys

def setup_logging(level=logging.INFO):
    """Configure logging for the entire application."""
    
    # Clear existing handlers
    root = logging.getLogger()
    root.handlers.clear()
    
    # Create formatters
    console_format = logging.Formatter(
        "%(asctime)s [%(levelname)s] %(name)s: %(message)s",
        datefmt="%H:%M:%S"
    )
    
    file_format = logging.Formatter(
        "%(asctime)s [%(levelname)s] %(name)s %(filename)s:%(lineno)d: %(message)s"
    )
    
    # Console handler
    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setLevel(level)
    console_handler.setFormatter(console_format)
    
    # File handler with rotation
    from logging.handlers import RotatingFileHandler
    file_handler = RotatingFileHandler(
        "app.log", maxBytes=10_000_000, backupCount=5
    )
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(file_format)
    
    # Configure root logger
    root.setLevel(logging.DEBUG)
    root.addHandler(console_handler)
    root.addHandler(file_handler)
    
    # Suppress noisy libraries
    logging.getLogger("urllib3").setLevel(logging.WARNING)
    logging.getLogger("httpx").setLevel(logging.WARNING)

# main.py
from logging_config import setup_logging
setup_logging(level=logging.INFO)

logger = logging.getLogger(__name__)
logger.info("Application started")

Fix 2: JSON structured logging for production

import logging
import json
import sys
from datetime import datetime

class JSONFormatter(logging.Formatter):
    def format(self, record):
        log_entry = {
            "timestamp": datetime.utcnow().isoformat(),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
            "module": record.module,
            "function": record.funcName,
            "line": record.lineno,
        }
        if record.exc_info:
            log_entry["exception"] = self.formatException(record.exc_info)
        return json.dumps(log_entry)

def setup_json_logging():
    root = logging.getLogger()
    root.handlers.clear()
    
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JSONFormatter())
    root.addHandler(handler)
    root.setLevel(logging.INFO)

# Usage
setup_json_logging()
logger = logging.getLogger("trading")
logger.info("Order executed", extra={"order_id": 12345, "amount": 1000})

Output:

{"timestamp": "2024-11-01T10:30:00.123456", "level": "INFO", "logger": "trading", "message": "Order executed", "module": "trader", "function": "execute", "line": 42}

Fix 3: Per-module logging levels

import logging

# Set different levels for different modules
logging.getLogger("myapp.database").setLevel(logging.DEBUG)
logging.getLogger("myapp.api").setLevel(logging.INFO)
logging.getLogger("myapp.trading").setLevel(logging.WARNING)

# Or disable specific noisy loggers
logging.getLogger("urllib3").disabled = True

Fix 4: Conditional logging for performance

import logging

logger = logging.getLogger(__name__)

# This avoids string formatting if DEBUG is disabled
if logger.isEnabledFor(logging.DEBUG):
    logger.debug(f"Order details: {order}")  # Only evaluated if DEBUG

# Or use lazy formatting (recommended)
logger.debug("Order details: %s", order)  # Formatting happens only if logged

Lessons Learned

• Configure logging at the application entry point, not in individual modules.
• Use RotatingFileHandler to prevent log files from growing unbounded.
• Disable propagation on module loggers if you add handlers directly to them.
• Use %s formatting instead of f-strings in log calls to avoid unnecessary string formatting.
• Set up structured JSON logging for production to enable log aggregation and analysis.

This blog does not accept any external sponsorships, affiliate marketing, or ad revenue.