1. Introduction: Structured Logging for AI

Description

The current state of many AI apps in production: print(response) as "logging". When something fails at 3am, debugging is adding more prints and redeploying. Structured logging replaces that with queryable data that lets you answer any question about what happened in your system — without touching the code. This capsule introduces the concept, the radical difference from traditional logging, and why it's especially critical for AI systems.

The situation without structured logging

# Typical AI app without professional logging:
def analyze_sentiment(text: str) -> dict:
    print(f"Processing: {text[:50]}...")  # "Logging"
    
    response = client.chat.completions.create(
        model="gpt-4o-mini",
        messages=[{"role": "user", "content": text}]
    )
    
    result = parse_response(response)
    print(f"Done: {result['sentiment']}")  # "Logging"
    return result

# When something fails in production:
# - How long did it take? Don't know
# - How many tokens did it use? Don't know
# - How much did it cost? Don't know
# - What input caused the error? Don't know
# - How many times did it happen? Don't know
# - Did any guardrail activate? Don't know

# The "debugging" is:
# 1. "Let me add more prints"
# 2. Deploy
# 3. Wait for it to happen again
# 4. Look at the prints
# Debugging latency: hours or days

The situation with structured logging

# The same app with structured logging:
def analyze_sentiment(text: str, request_id: str) -> dict:
    log = structlog.get_logger().bind(request_id=request_id)
    start = time.time()
    
    log.info("llm_request_started", text_length=len(text))
    
    response = client.chat.completions.create(
        model="gpt-4o-mini",
        messages=[{"role": "user", "content": text}]
    )
    
    duration_ms = (time.time() - start) * 1000
    cost = calculate_cost(response.usage)
    
    log.info("llm_request_completed",
        model="gpt-4o-mini",
        input_tokens=response.usage.prompt_tokens,
        output_tokens=response.usage.completion_tokens,
        duration_ms=duration_ms,
        cost_usd=cost
    )
    
    result = parse_response(response)
    return result

# When something fails in production:
# → "request_id=abc123 has a 500 error at 3am"
# → grep "abc123" logs.json
# {"event": "llm_request_started", "request_id": "abc123", "text_length": 4500}
# {"event": "llm_request_completed", "request_id": "abc123", "duration_ms": 15234}  ← 15 seconds!
# {"event": "pydantic_validation_failed", "request_id": "abc123", "error": "truncated JSON"}
# Complete story in 30 seconds.

Traditional vs structured logging: the fundamental difference

# ─── TRADITIONAL logging ──────────────────────────────────────────
import logging
logger = logging.getLogger(__name__)

logger.info("Request processed in 2.3 seconds by gpt-4o-mini, 450 tokens")
# Output: "2024-01-15 10:30:00 INFO Request processed in 2.3 seconds by gpt-4o-mini, 450 tokens"

# To search for all requests that took more than 10s:
# → grep with a complicated regex
# → You can't sum durations
# → You can't sort by tokens
# → You can't filter by model

# ─── STRUCTURED logging ───────────────────────────────────────────
import structlog
log = structlog.get_logger()

log.info("request_completed",
    duration_ms=2300,
    model="gpt-4o-mini",
    tokens=450,
    cost_usd=0.000068
)
# Output: {"event": "request_completed", "duration_ms": 2300, "model": "gpt-4o-mini",
#           "tokens": 450, "cost_usd": 0.000068, "timestamp": "2024-01-15T10:30:00Z"}

# To search for slow requests:
# jq 'select(.duration_ms > 10000)' logs.json ← trivial

# To calculate the day's total cost:
# jq '[.cost_usd] | add' logs.json ← one line

# To find the most expensive model:
# jq -r 'select(.cost_usd > 0.1) | .model' logs.json ← trivial

Why structured logging is especially critical for AI

In traditional web apps, failures are deterministic: same input → same output → same error. In AI apps, failures are non-deterministic:

Problem 1: A user reports "the response was really weird"
Without logging: "What exactly was their question? Which model did we use? What temperature?"
With logging: search for the request_id, see the exact prompt, model, temperature, output, duration

Problem 2: An unexpectedly high OpenAI bill this month
Without logging: "I don't know what's generating so much cost"
With logging: query by cost_usd > 0.05, find that an edge case generates enormous prompts

Problem 3: The injection guardrail detected many attacks yesterday
Without logging: You had no way to know
With logging: automatic alert when guardrail_activations > 10/hour, investigate with request_ids

Problem 4: Migration from gpt-4o to gpt-4o-mini
Without logging: "I don't know if the new model is just as good"
With logging: compare metrics before and after: avg_duration_ms, avg_cost_usd, error_rate

The 4 dimensions of AI logging

Dimension 1: REQUEST LIFECYCLE
  ┌──────────────────────────────────────────────────────┐
  │ request_id = "abc123" (connects all the events)      │
  │                                                      │
  │ input_received → sanitized → injection_check →      │
  │ llm_called → llm_responded → validated →            │
  │ pii_redacted → output_sent                          │
  └──────────────────────────────────────────────────────┘

Dimension 2: PERFORMANCE
  - duration_ms (how long each step takes)
  - queue_time_ms (time spent waiting)
  - llm_latency_ms (how long the LLM takes)

Dimension 3: COST
  - input_tokens, output_tokens
  - cost_usd (calculated)
  - model used

Dimension 4: GUARDRAILS
  - guardrail activated or not
  - guardrail type
  - action taken (blocked/modified)

Questions that structured logging lets you answer

With a well-configured logging system, these are the queries you can run about your app in production:

# What is today's total cost?
jq -s '[.[].cost_usd // 0] | add' logs.json

# What are the 10 most expensive requests?
jq -s 'sort_by(-.cost_usd) | .[0:10] | .[] | {request_id, cost_usd, duration_ms}' logs.json

# How many requests failed in the last hour?
jq 'select(.level == "error" and .timestamp > "2024-01-15T09:00:00Z")' logs.json | wc -l

# How many guardrails activated today?
jq 'select(.event == "guardrail_activated")' logs.json | wc -l

# What is the average latency per model?
jq -s 'group_by(.model) | map({model: .[0].model, avg_ms: ([.[].duration_ms] | add / length)})' logs.json

# Which request caused the 3am error?
jq 'select(.level == "error" and (.timestamp | startswith("2024-01-15T03:")))' logs.json

The module's mental shift

Before:
  → "I have an error in production, I'll add prints and redeploy"
  → "I don't know how much each request costs"
  → "A user reported something weird, I can't reproduce it"

After:
  → "I have the error's request_id, I search the logs and see the whole stack"
  → "I know exactly how much each model and each endpoint costs"
  → "With the request_id I reproduce the problem in 2 minutes"

Module prerequisites

# Main dependencies
pip install structlog python-json-logger

# Optional but recommended
pip install colorama  # For colors in ConsoleRenderer (development)

Module roadmap

Exercises

Exercise 1: The cost of NOT having logging

For your current app, list 3 questions you CAN'T answer without structured logging:

Exercise 2: Design the schema for a request log

Define the fields that a completed-request log should have in your app:

# Schema for the completed-request log:
{
    # Identification
    "event": "request_completed",
    "request_id": "abc12345",          # Short UUID, unique per request
    "timestamp": "2024-01-15T10:30:00Z",
    
    # Request info
    "endpoint": "/analyze",
    "method": "POST",
    
    # LLM info
    "model": "gpt-4o-mini",
    "input_tokens": 245,
    "output_tokens": 87,
    "cost_usd": 0.0000888,
    
    # Performance
    "duration_ms": 1240,
    "llm_latency_ms": 1150,
    
    # Result
    "level": "info",
    "status_code": 200,
    
    # Guardrails
    "guardrails_activated": [],     # List of guardrails that activated
    
    # Optional (only in debug or error)
    # "prompt_hash": "abc123ef",    # Hash of the prompt for reproducibility
}

Exercise 3: Convert a print() to a structured log

Convert this code to structured logging:

print(f"User {user_id} request took {duration}s, used {tokens} tokens")

import structlog
log = structlog.get_logger()

log.info(
    "request_completed",
    user_id=hash(user_id),      # Hash for privacy
    duration_ms=int(duration * 1000),
    tokens_used=tokens,
    request_id=request_id
)
# JSON output: {"event": "request_completed", "user_id": 1234567,
#               "duration_ms": 2300, "tokens_used": 450, "request_id": "abc123"}

Exercise 4: Identify what to log in your app

For the /analyze endpoint of the sentiment app, list the 5 most important events you should log:

Summary

• Structured logging = queryable data, not free text
• The transformation: from print() to logs that answer questions in 30 seconds
• 4 critical dimensions for AI: request lifecycle, performance, cost, guardrails
• Correlation IDs are the common thread: everything connected by request_id
• It's not overhead — it's infrastructure: like tests or guardrails, it's not optional for production

Additional resources

1. structlog Documentation — The main library for this module
2. The Twelve-Factor App: Logs — The "logs as event streams" philosophy
3. JSON Lines format — The standard format for JSON logs
4. jq Tutorial — For querying JSON logs
5. OpenTelemetry — For when you need advanced distributed tracing
6. Observability Engineering (O'Reilly) — The reference book on observability