Lesson 45 — Structured logging

Exercise 1 — The JSON formatter

1. The verification line:

{"asctime": "2027-09-28T14:22:03Z", "levelname": "info", "name": "reservations.service",
 "message": "reservation_confirmed", "trace_id": "7c9e6679-7425-40de-944b-e07fc1f90ae7",
 "version": "a1b2c3d", "ref": "RF-8A21", "user_id": "u-841", "duration_ms": 183}

jq. /tmp/app.log parses it without error: the format's test.

1. The habit change: logger.info(f"reserva {ref} confirmada") → logger.info("reservation_confirmed", extra={"ref": ref}). The empty grep is the rule: data goes in extra (filterable) and message is the event's verb (groupable). The fine reason: the f-string destroys cardinality — 500 reservations produce 500 "distinct messages" the index can't group; the event with extra produces ONE message × 500 lines with a different ref: groupable and filterable.

1. The TZ: the log records UTC ALWAYS (the formatter's ts in UTC — the collector and the other services' correlator expect it); business time (the event starts at 20:00 the buyer's local time) is a domain field (31: the event's TZ), not the log's. Mixed TZs in the log are the classic: two systems 2 h apart correlating the incident wrongly.

Exercise 2 — The trace_id

1. The no-mixing evidence: two concurrent threads, each request with its tid:

{"trace_id": "aaa-...", "event": "reservation_created", ...}
{"trace_id": "bbb-...", "event": "reservation_created", ...}

With threading.local + async (16): the event loop's context shares the thread's local → the tids mix (the ghost incident: request A's log contains B's data). contextvars is the correct primitive for async and threads.

1. The queue: the task's kwargs carry the tid; the task re-sets it FIRST:

@shared_task
def enviar_email_confirmacion(ref, trace_id=None):
    trace_id_var.set(trace_id or "-")
    ...

The eager test: the task's log carries the tid of the request that enqueued it. In prod (separate worker), the tid travels in the Celery message: the thread doesn't break at the queue.

1. The complete E2E thread: X-Request-ID in the response → the same tid in the endpoint's log → in the outbox's payload → in the consumer's log sending the fake email. 47's query ("what happened to THIS reservation?") is a grep by tid returning the full life — 4 systems, one thread.

Exercise 3 — The catalog

1. The table (~12 excerpt):

1. The reclassified: the request's 404/401 is NOT an ERROR (the Internet scanner generates thousands: 26 already decided; django.request to WARNING); gateway_retry is WARNING (recoverable, 46's metric counts it); login_failed WARNING (a brute-force signal) but login_success INFO in audit. The suite's healthy ratio: <5% of lines at WARNING+ERROR — if noise eats the signal, the level is wrong and NOBODY will read the real ERROR.

1. The PII findings: logger.info("reserva recibida", extra={"body": request.data}) (the body carries the buyer's email/phone: NEVER; it gets user_id and ref) and django.db.backends at DEBUG (SQL with parameters: the user's payload into the index; at WARNING). The fix with the principle: the log carries IDENTIFIERS (the data lives in the DB with its controlled access), never CONTENT.

Exercise 4 — The diagnostic query

1. RF-8A21's story:

jq 'select(.ref=="RF-8A21" or .trace_id==(jq 'select(.ref=="RF-8A21")' app.log | jq -r '.[0].trace_id'))' app.log
# → reservation_created (tid 7c9e...) → payment_pending → gateway_retry (WARNING ×2)
#   → payment_succeeded → saga CONFIRMED → email_sent: the full story in 1 command

1. The log access policy: the per-user query IS a personal-data query: the policy (23/56) — only the on-call with an incident ticket (the log stores the queries if the stack allows), anonymized results in the postmortem, and administrative access to the index with its own audit. A log anyone can query for any user is a PII dump with a search interface.

1. The retention with numbers: ~500 logs/reservation (the course) × 50k reservations/month × ~400 B = ~10 GB/month hot (30 days: 10 GB) + compressed cold (~2 GB/month): the cost is ~€2-5/month: cheap; the decision belongs to 56 (does the regulator demand 1 year?) and 23 (PII alive in the log for a year? — identifiers yes, content never enters).

Exercise 5 — Audit vs log

1. The decided double life: YES to both with distinct purposes — the audit log (table) answers "who did what" with integrity (append-only, no UPDATE/DELETE, 23) for the auditor/regulator; the log answers "what happened in the system" with technical context (tid, duration). login_success: an audit row (the auditor demands it) + an INFO log (diagnosis uses it). What lives only in audit: the export download (access to personal data: the GDPR demands it be provable).

1. The queries: the auditor: SELECT * FROM audit_log WHERE action='role_changed' AND ts BETWEEN... (56's query: who escalated to staff and when); the diagnosis: jq 'select(.event=="role_changed")' with tid and context. Each serves its client: the regulator doesn't read log JSON, the on-call doesn't want the audit's SQL.

1. The error top 46 will alert on:

jq -r 'select(.levelname=="error") | .message' app.log | sort | uniq -c | sort -rn | head 5
#   412 saga_unknown_expirada      ← the alert candidate
#    87 dlq_push
#    12 gateway_hard_fail

This lesson's query is the next lesson's alert seed: the ERROR grouped by event with a threshold — the natural step from log to metric.

Professor's summary

• JSON per line with a fixed contract (ts UTC, level, event, trace_id, version); data in extra (groupable), never f-strings (cardinality destroyed).
• The trace_id is born at the edge and travels through queue and outbox with contextvars; the tid query is 47's thread.
• INFO = business facts, WARNING = anomalous-recoverable, ERROR = action required; identifiers yes, content/PII never; the audit log is another thing (append-only, for the regulator).