112. Logging Module

🪵 A system replaces scattered print() calls with structured logging. The developer used the wrong log method signature, got an anonymous logger instead of a named one, and set the log level too late for messages to appear.

💡 Fun fact: Python’s logging module was added in Python 2.3 (2003) and was inspired by Java’s log4j logging framework. The module uses a hierarchy of loggers — logging.getLogger("myapp.module") is a child of logging.getLogger("myapp"), which inherits its parent’s level. This hierarchy is why logging.getLogger(__name__) works so well in large packages: you can silence an entire subpackage with one setting.

⚠️ Watch out: logging.basicConfig() only has an effect if the root logger has no handlers yet. If you call it after any log messages have been sent (or after any other module calls it first), your basicConfig() call is silently ignored. This is why log messages sometimes don’t appear — call basicConfig() at the very start of your program, before importing any module that might trigger logging.

🤔 Think about it: print() always outputs to stdout. logger.debug() does nothing if the level is INFO or higher. This means you can leave logger.debug() calls in production code — they have no performance cost when disabled. When would you use logger.debug() in production code rather than removing the debug statement entirely?

Learning objectives

• Use logger.info(), logger.warning(), logger.error() instead of logging.log(string, msg)
• Create named loggers with logging.getLogger(name) for module-level control
• Configure logging with basicConfig before any messages are sent
• Convert level name strings to integer constants with getattr(logging, name)
• Capture log output in tests using StringIO and StreamHandler

Key concepts

• logging.getLogger(name) — named logger
• basicConfig(level=, format=) — one-time setup
• logger.debug/info/warning/error/critical() — level methods
• logging.DEBUG/INFO/WARNING/ERROR/CRITICAL — integer constants
• StreamHandler + StringIO — capture logs in tests

Try it

Concept detail

logging — Structured Logging in Python

Replace print() with logging for production code. Logging gives you levels, filtering, formatting, and output destinations for free.

Basic Setup

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s"
)
logger = logging.getLogger(__name__)

Log Levels (low to high)

Named Loggers

# Always use __name__ — gives you module-level filtering
logger = logging.getLogger(__name__)
# In package/module.py, this creates logger named "package.module"

Capturing Logs in Tests

import logging, io
stream = io.StringIO()
handler = logging.StreamHandler(stream)
logging.getLogger().addHandler(handler)
# ... run code ...
output = stream.getvalue()
assert "ERROR" in output

Converting String Level Names

level_name = "DEBUG"
level = getattr(logging, level_name.upper(), logging.INFO)
logging.basicConfig(level=level)

Solution

import logging

# FIX 1: Named logger — use __name__ so logs identify their source module
logger = logging.getLogger(__name__)

def setup_logging(level_name="DEBUG"):
    """Configure logging for the application."""
    # FIX 2: Use getattr to convert level string to integer constant
    level = getattr(logging, level_name.upper(), logging.DEBUG)
    logging.basicConfig(
        format="%(levelname)s:%(name)s:%(message)s",
        level=level,
    )
    logger.setLevel(level)

def process_order(order_id, amount):
    """Process an order and log each step."""
    # FIX 3: Use logger.info() / logger.warning() — correct method names
    logger.info(f"Processing order {order_id} for ${amount}")
    if amount > 1000:
        logger.warning(f"Large order detected: ${amount}")
    return {"order_id": order_id, "status": "processed", "amount": amount}

def divide(a, b):
    """Divide a by b, logging errors on failure."""
    try:
        result = a / b
        logger.info(f"Divided {a} / {b} = {result}")
        return result
    except ZeroDivisionError:
        logger.error(f"Division by zero: {a} / {b}")
        return None

Tests

import logging
import io

def test_process_order_returns_dict():
    result = process_order("ORD-001", 500)
    assert isinstance(result, dict)
    assert result["order_id"] == "ORD-001"
    assert result["status"] == "processed"

def test_process_order_large_amount_returns_correctly():
    result = process_order("ORD-002", 1500)
    assert result["amount"] == 1500
    assert result["status"] == "processed"

def test_divide_normal():
    assert divide(10, 2) == 5.0

def test_divide_by_zero_returns_none():
    result = divide(5, 0)
    assert result is None, "divide by zero should return None"

def test_logging_log_method_does_not_crash():
    """logging.log('INFO', msg) crashes — solution should use logger.info()"""
    # This test verifies process_order doesn't raise TypeError
    try:
        process_order("ORD-003", 200)
        passed = True
    except TypeError:
        passed = False
    assert passed, "process_order should not raise TypeError from bad logging.log() call"

def test_logger_has_name():
    """Logger should not be anonymous (empty string name)"""
    # The logger variable in the module should have a meaningful name
    assert logger.name != "root", "Use logging.getLogger(__name__), not getLogger()"
    assert logger.name != "", "Logger must have a name"

def test_setup_logging_accepts_string_level():
    """setup_logging('DEBUG') should not crash"""
    try:
        setup_logging("DEBUG")
        setup_logging("INFO")
        passed = True
    except Exception:
        passed = False
    assert passed, "setup_logging should accept string level names like 'DEBUG'"

def test_divide_captures_log_on_error():
    """divide(5, 0) should log an error, not crash silently"""
    log_stream = io.StringIO()
    handler = logging.StreamHandler(log_stream)
    handler.setLevel(logging.DEBUG)
    # Attach handler to root logger to catch all messages
    root = logging.getLogger()
    root.addHandler(handler)
    root.setLevel(logging.DEBUG)
    divide(5, 0)
    root.removeHandler(handler)
    output = log_stream.getvalue()
    # The function returned None — that's the side-effect we can test without log capture
    assert divide(5, 0) is None

Resources

• logging — Logging facility for Python
• Logging HOWTO — Python Docs
• Corey Schafer — Logging Tutorial
• Python Logging: A Stroll Through the Source Code — Real Python
• W3Schools — Python Logging