Lesson 45 — Structured logging

Stack: Django + JSON logging · Project: TicketFlow Status: Published — opening the observability module Prerequisite: Lesson 44 — Infrastructure as code (Terraform)

Objectives

1. Replace text logs with structured logs (JSON) with levels, context and the trace_id that follows a request end to end.
2. Configure Django/DRF logging with per-request context (middleware) without leaking PII (23).
3. Decide what gets logged and at which level, using the principle: the log is for diagnosing, not narrating.

1. From text to JSON: why structure wins

The text log (ERROR 2027-09-28... reservation failed for user juan) is for human eyes on a terminal; at scale (10k requests/hour, 47's desperate grep) it is unqueryable noise. JSON with stable keys gets filtered, grouped and correlated: {"level": "error", "event": "reservation_failed", "trace_id": "7c9e...", "user_id": "u-841", "reason": "seat-unavailable"}. The format rule: every line is ONE valid JSON event (one log per line: the provider's collector cuts by line); keys stable and in English (event, level, trace_id) because the one filtering is not you — it is the log stack's index.

{"ts": "2027-09-28T14:22:03.114Z", "level": "info", "logger": "reservations.service",
 "event": "reservation_confirmed", "trace_id": "7c9e6679-...", "user_id": "u-841",
 "ref": "RF-8A21", "duration_ms": 183, "env": "prod", "version": "a1b2c3d"}

The contract keys: ts (ISO8601 UTC ALWAYS — 31's classic is the server's local TZ), level, event (a domain verb-in-past, not the function's name), trace_id (§2), and the business context (ref, user_id, event_id). And the release ones: env and version (41's commit) in ALL lines — a mixed deployment's log (blue/green coexisting, 41) separates by version without guessing.

2. The trace_id: the backbone

The trace_id is a UUID generated when the request ENTERS (at the edge/middleware) and propagated: into THAT request's logs, into the Celery tasks it enqueues (the id travels in the task's kwargs), into the outbox events (25), into the errors' problem+json (26: the client can report it) and into the outgoing headers (X-Request-ID). The diagnostic query: "trace_id=7c9e... " returns the ENTIRE life of the customer's order: the request, the saga, the emails, the webhook — the thread 47 pulls. The context middleware:

# core/logging.py
import contextvars, uuid

trace_id_var = contextvars.ContextVar("trace_id", default=None)

class TraceIdMiddleware:
    def __init__(self, get_response): self.get_response = get_response
    def __call__(self, request):
        tid = request.headers.get("X-Request-ID") or str(uuid.uuid4())
        trace_id_var.set(tid)
        response = self.get_response(request)
        response["X-Request-ID"] = tid
        return response

class ContextFilter(logging.Filter):
    def filter(self, record):
        record.trace_id = trace_id_var.get() or "-"
        record.version = os.environ.get("APP_VERSION", "dev")
        return True

contextvars (not threading.local): correct under async (16) and per-thread — the detail preventing two requests from mixing trace_ids under gunicorn with threads.

3. Django's logging, configured grown-up

# settings.py
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "filters": {"context": {"()": "core.logging.ContextFilter"}},
    "formatters": {"json": {"()": "pythonjsonlogger.jsonlogger.JsonFormatter",
                            "format": "%(asctime)s %(levelname)s %(name)s %(message)s"}},
    "handlers": {"stdout": {"class": "logging.StreamHandler",
                            "filters": ["context"], "formatter": "json", "stream": "ext://sys.stdout"}},
    "root": {"handlers": ["stdout"], "level": "INFO"},
    "loggers": {
        "reservations": {"level": "INFO"},
        "django.request": {"level": "WARNING"},   # request 4xxs: WARNING, not ERROR spam
        "django.db.backends": {"level": "WARNING"},  # never DEBUG in prod: SQL carries parameters (PII, 23)
    },
}

The contract's decisions: logs go to STDOUT (40's container writes no files: the platform's collector picks them up — the local file is the one that rotates badly and fills 47's disk); django.request at WARNING (every 404/401 as ERROR floods the index: 26 already decided the 401 is noise); django.db.backends never at DEBUG in prod (SQL with parameters prints the user's payload: PII into the log, 23). The per-logger level is config (27) defaulting to INFO — the global DEBUG is the incident's emergency button (47) with a short window.

4. What gets logged (and what doesn't): the event catalog

TicketFlow's minimal catalog with levels: INFO (consummated domain events: reservation_confirmed, payment_succeeded, saga_compensated, outbox_published — what the business would write in its ledger, 08's ledger as a log); WARNING (the anomalous-recoverable: gateway retry, 29's dedup firing, 31's lock skip, 23's rate limit); ERROR (requiring action: expired saga UNKNOWN, DLQ > 0, task_failed); CRITICAL (reserved: confirmed money loss). And what does NOT go in: full request/response payloads (PII, 23 — the body field the user typed: NEVER), auth tokens/headers, SQL at DEBUG. The "log everything" alias: 56/23's audit log is a different append-only TABLE (regulatory, with who/when/what) — don't mix it with the diagnostic log.

logger.info("reservation_confirmed", extra={"ref": r.public_ref, "user_id": r.user_id,
                                            "duration_ms": 183})   # extra: the contract's keys

logger.info(msg, extra=...) with flat keys (the JsonFormatter serializes them): the habit is extra ALWAYS (never f-strings with data: f"reserva {ref}" produces logs unfilterable by ref).

5. Correlation in async and the pipeline's test

Celery tasks (29) receive the trace_id in their kwargs (enviar_email.delay(ref, trace_id=tid)) and re-set it when the task starts (trace_id_var.set(kwargs["trace_id"])): the customer's email is traceable from the endpoint to the worker. The outbox (25) carries the trace_id in the event's payload: the consumer restores it. The pipeline's test (34/35 integrates it):

def test_trace_id_sobrevive_a_la_cola(self):
    with captureOnCommitCallbacks(execute=True):
        reservar(...)                      # the test's middleware set a known tid
    logs = [r for r in self.caplog.records if r.trace_id == TID]
    assert any(r.event == "reservation_confirmed" for r in logs)

And the stack's retention: 30 days hot + 1 year cold (or whatever 56 demands): "three weeks ago there was a double charge" gets investigated with the log available, not with the on-call's memory summary.

Self-assessment

1. Why does JSON beat text at scale, and what are the minimum contract keys of every line?
2. Where is the trace_id born, how does it propagate in TicketFlow (endpoint→queue→outbox), and what does the trace_id query enable?
3. Why contextvars and not threading.local? What does mixing trace_ids break?
4. What goes to INFO/WARNING/ERROR in TicketFlow's catalog, and what NEVER enters the log (23)?
5. Why do logs go to STDOUT, and which two LOGGING decisions avoid both spam and PII leaks?

Continue with the exercises. The solutions only after trying it yourself.