4.6Log-Based Testing

Structured logs enable a powerful testing pattern: assert on log output to verify system behavior:

# test_order_logging.py
import json

def test_order_flow_produces_expected_logs(capsys, order_service):
    """Verify the order flow logs all expected events."""
    order_service.process_order("user_1", "order_1", [{"sku": "A", "qty": 1}])

    captured = capsys.readouterr()
    log_lines = [json.loads(line) for line in captured.out.strip().split('\n')]

    # Verify expected events are logged in order
    events = [log["event"] for log in log_lines]
    assert "order_processing_started" in events
    assert "order_total_calculated" in events
    assert "payment_processed" in events
    assert "inventory_reserved" in events
    assert "order_processing_completed" in events

    # Verify context is propagated
    for log in log_lines:
        assert log["user_id"] == "user_1"
        assert log["order_id"] == "order_1"

    # Verify timing data is present
    completed = next(l for l in log_lines if l["event"] == "order_processing_completed")
    assert "duration_ms" in completed
    assert completed["duration_ms"] > 0