# 0011. Python structured logging with structlog and request context ## Status Proposed ## Context The service needs application-level Python logging in addition to the durable Postgres records from ADR-0009 and the LLM/agent traces from ADR-0010. Postgres audit tables answer durable business questions such as which tenant API key called an endpoint, which point mutation was requested, which ingestion job ran, and what usage ledger rows were produced. Langfuse answers LLM observability questions such as which graph node or prompt version produced an answer. Structured Python logs answer operational questions while the service is running: - Which request failed and where? - Which logs belong to one FastAPI request or LangGraph run? - Which tenant, API key, thread, run, file, point, or ingestion job was involved? - Which dependency was slow or unavailable? - Which fallback path or retry was used? FastAPI, LangGraph, SQLAlchemy, Qdrant, Langfuse, and HTTP clients can all emit logs from asynchronous code. Since async tasks can interleave on the same event loop, relying on process-global mutable variables is unsafe. The logging context must be request-scoped and safe across async task switching. Python `contextvars`, exposed through `structlog.contextvars`, provide this behavior. The user has used a previous `log.py` based on `logging`, `structlog`, `logging.config.dictConfig`, `ProcessorFormatter`, JSON rendering, stdlib log capture, and manual `ContextVar` fields such as `session_id` and `property_id`. This service should keep the same core idea but adapt the field names to the current architecture: - `thread_id` instead of `session_id` for LangGraph conversations, matching ADR-0007 and ADR-0008; - `tenant_id`, `tenant_slug`, `api_key_id`, and `actor_type` from `AuthContext`; - `request_id` from FastAPI middleware; - `run_id` from `graph_runs` for chat runs; - `file_id`, `point_id`, and `ingestion_job_id` for ingestion and point work; - `langfuse_trace_id` when available for cross-navigation to ADR-0010 traces. ## Decision ### Use structlog as the application logging interface Use `structlog` for application logs and integrate it with Python stdlib logging so framework/library logs are formatted consistently. Application code imports loggers with: ```python import structlog logger = structlog.get_logger(__name__) ``` Log events use stable event names and structured fields: ```python logger.info( "graph.run.completed", status="answered", duration_ms=duration_ms, retrieved_chunk_count=len(retrieved_chunks), ) ``` Do not build log messages by interpolating operational metadata into prose. Prefer fields over long strings because fields are queryable. ### Emit JSON logs by default in production; console and file are independent sinks locally Production logs are JSON on stdout so process managers, container runtimes, and log collectors can ingest them directly. This does not change. Locally, stdout and an optional file are two **independent, simultaneous** handlers on the same logger, not a single renderer chosen by a flag — the same structlog event fans out to both: - **Console handler**: always on, `structlog.dev.ConsoleRenderer(colors=True)`. This is what a developer reads while the process runs, so it stays human-readable regardless of whether file logging is also enabled. - **File handler**: off by default, enabled by setting `LOG_FILE_PATH`. Always renders JSON (`structlog.processors.JSONRenderer()`), independent of the console handler's renderer, so a saved log is machine-parseable even though the terminal output next to it is not. Must use explicit rotation (`RotatingFileHandler` with `maxBytes`/`backupCount` — never an unrotated handler). In containerized production, stdout/stderr collection remains preferred over writing `logs/app.log` inside the application container, so `LOG_FILE_PATH` is expected to be unset there; the file handler exists for local development, where reading a colored terminal *and* keeping a JSON trail to grep/parse later are both useful at once. ### Configure stdlib and structlog together The logging setup should happen once during process startup, before the FastAPI app begins serving requests. Indicative configuration shape: ```python import logging import logging.config import sys import structlog def configure_logging(*, log_level: str, json_logs: bool) -> None: shared_processors = [ structlog.contextvars.merge_contextvars, structlog.stdlib.add_log_level, structlog.stdlib.add_logger_name, structlog.processors.TimeStamper(fmt="iso", utc=True), structlog.processors.StackInfoRenderer(), ] structlog.configure( processors=[ *shared_processors, structlog.processors.format_exc_info, structlog.stdlib.ProcessorFormatter.wrap_for_formatter, ], logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, cache_logger_on_first_use=True, ) renderer = ( structlog.processors.JSONRenderer() if json_logs else structlog.dev.ConsoleRenderer(colors=True) ) logging.config.dictConfig( { "version": 1, "disable_existing_loggers": False, "formatters": { "default": { "()": structlog.stdlib.ProcessorFormatter, "processors": [ structlog.stdlib.ProcessorFormatter.remove_processors_meta, renderer, ], "foreign_pre_chain": [ structlog.stdlib.ExtraAdder(), *shared_processors, ], }, }, "handlers": { "console": { "class": "logging.StreamHandler", "level": log_level, "formatter": "default", "stream": sys.stdout, }, }, "loggers": { "": { "handlers": ["console"], "level": log_level, "propagate": False, }, "uvicorn": { "handlers": ["console"], "level": log_level, "propagate": False, }, "uvicorn.access": { "handlers": ["console"], "level": log_level, "propagate": False, }, "sqlalchemy.engine": { "handlers": ["console"], "level": "WARNING", "propagate": False, }, "watchfiles": { "handlers": ["console"], "level": "INFO", "propagate": False, }, }, } ) ``` Notes: - Use the logger name `sqlalchemy.engine`, not `sqlalchemy.engin`. - SQL statement logging is too noisy and can leak values; keep it `WARNING` by default in production and enable `INFO`/`DEBUG` only in controlled debugging. - `structlog.stdlib.ExtraAdder()` keeps useful fields from stdlib log records. - `structlog.contextvars.merge_contextvars` ensures request-bound fields appear on both structlog and stdlib logs processed through the formatter. ### Bind process-level environment context once at startup Deployment identity — which build is running, in which environment, on which instance — answers a different question than request correlation: "is this issue specific to one deployment / one region / one instance?" rather than "is this issue specific to one request?" It does not vary per request, so it must not go through `structlog.contextvars`, which `RequestIdMiddleware` clears on every request; a value bound there before the first request would be wiped the moment that middleware runs. Instead, add a static structlog **processor** — a plain closure over values read once at `configure_logging()` time — so it runs on every event regardless of request context: ```python def _bind_environment(settings: AppLimitSettings): def processor(logger, method_name, event_dict): event_dict["env"] = settings.env event_dict["service_version"] = settings.service_version return event_dict return processor ``` `service_version` should be the deployed commit SHA or release tag (e.g. from a `GIT_SHA`/`APP_VERSION` build-time env var — not computed at runtime by shelling out to `git`). This makes "is this only happening on the new deployment?" answerable directly from logs, without cross-referencing a separate deployment record. ### Bind request context with contextvars At FastAPI ingress, clear stale context, bind request identifiers, and return the request id to callers. This makes it possible to select all logs from one request or one graph run even when async tasks interleave. Indicative middleware: ```python from time import perf_counter from uuid import uuid4 import structlog from fastapi import Request from starlette.types import ASGIApp REQUEST_ID_HEADER = "X-Request-ID" async def logging_context_middleware(request: Request, call_next: ASGIApp): structlog.contextvars.clear_contextvars() request_id = request.headers.get(REQUEST_ID_HEADER) or str(uuid4()) route = request.scope.get("route") path_template = getattr(route, "path", request.url.path) structlog.contextvars.bind_contextvars( request_id=request_id, method=request.method, path_template=path_template, ) logger = structlog.get_logger("app.http") started = perf_counter() logger.info("request.started") try: response = await call_next(request) except Exception: logger.exception( "request.failed", duration_ms=round((perf_counter() - started) * 1000, 2), ) raise response.headers[REQUEST_ID_HEADER] = request_id logger.info( "request.completed", status_code=response.status_code, duration_ms=round((perf_counter() - started) * 1000, 2), ) return response ``` After API-key authentication succeeds, the auth dependency or route handler binds trusted tenant/auth fields: ```python structlog.contextvars.bind_contextvars( tenant_id=str(auth.tenant_id), tenant_slug=auth.tenant_slug, api_key_id=str(auth.api_key_id), actor_type=auth.actor_type, ) ``` Route handlers bind route-specific fields when they become known: ```python structlog.contextvars.bind_contextvars( external_user_id=body.user_id, thread_id=thread_id, run_id=str(run_id), ) ``` Use these canonical context keys: | Field | Source | Notes | |---|---|---| | `request_id` | FastAPI middleware | Primary log correlation id; also appears in ADR-0008/0009 records. | | `tenant_id` | `AuthContext` | Trusted server-side tenant id; never request body/query. | | `tenant_slug` | `AuthContext` | Useful for filtering; avoid if contractual policy treats it as sensitive. | | `api_key_id` | `AuthContext` | Non-secret id only. Never log raw API keys or auth headers. | | `actor_type` | `AuthContext` | `backend`, `admin`, or `worker`. | | `external_user_id` | Main backend | May be high-cardinality; acceptable in logs, not metrics labels. | | `thread_id` | REST path | LangGraph thread id. | | `run_id` | `graph_runs.id` | One chat run. | | `ingestion_job_id` | `ingestion_jobs.id` | File ingestion correlation. | | `file_id` | `source_files.id` | Source-file correlation. | | `point_id` | Qdrant point id | Point mutation/read correlation. | | `langfuse_trace_id` | Langfuse | Cross-link to ADR-0010 trace when available. | Use `structlog.contextvars.clear_contextvars()` at request/task ingress to avoid leaking a previous request's context into reused workers. ### Bind context explicitly for jobs and background work Context variables work across normal async task switching, but background jobs, worker processes, scheduled jobs, and threadpool work should bind context at their own entry point from durable identifiers. Examples: - ingestion worker binds `tenant_id`, `ingestion_job_id`, `file_id`, and `request_id` if inherited from the upload request; - LangGraph run execution binds `thread_id`, `run_id`, `tenant_id`, and `external_user_id` before invoking the graph; - point batch workers bind `tenant_id`, `api_request_log_id`, and operation metadata before processing each batch. If code crosses a boundary where contextvars may not propagate automatically, pass the identifiers explicitly and bind them again at the boundary. ### Log levels and event naming Use log levels consistently: | Level | Use | |---|---| | `DEBUG` | Local diagnostics, disabled by default in production. | | `INFO` | Normal lifecycle events: request started/completed, graph run completed, ingestion job completed. | | `WARNING` | Recoverable anomalies: fallback prompt used, retry scheduled, insufficient retrieval before clarification/escalation. | | `ERROR` | Failed operations requiring attention: unhandled exception, dependency outage, ingestion failure. | Do not log expected user behavior at `ERROR`. For example, a user asking an ambiguous question that leads to clarification is an `INFO` event; a retriever being unavailable is an `ERROR` event. Use stable dot-separated event names: - `request.started` - `request.completed` - `request.failed` - `auth.succeeded` - `auth.failed` - `graph.run.started` - `graph.run.completed` - `graph.run.escalated` - `retrieval.completed` - `retrieval.insufficient` - `llm.call.completed` - `llm.call.failed` - `ingestion.job.started` - `ingestion.job.completed` - `point.mutation.completed` Do not include dynamic values in logger names or event names. Put dynamic values in structured fields. ### Security and privacy rules Logs must not contain secrets or raw sensitive payloads. Never log: - plaintext API keys; - `Authorization` headers; - database URLs or provider credentials; - raw uploaded file contents; - full retrieved chunks by default; - raw user messages, raw prompts, or raw model outputs by default; - embeddings or vectors. Prefer: - ids (`request_id`, `thread_id`, `run_id`, `file_id`, `point_id`); - hashes (`input_message_hash`, `output_message_hash`, `content_sha256`); - counts, sizes, durations, and status codes; - short redacted summaries only when useful and allowed by tenant policy. The same redaction policy used for ADR-0009 `llm_call_payloads` and ADR-0010 Langfuse tracing should guide log redaction. Logging should be safe even when log aggregation has broader access than the application database. ### Relationship to Postgres and Langfuse Structured logs complement but do not replace ADR-0009 and ADR-0010. | Question | System of record | |---|---| | What happened operationally inside this process? | Structured logs. | | Which API key called which endpoint and what durable side effect occurred? | Postgres audit tables from ADR-0009. | | Which graph node, prompt version, retrieved chunks, and model calls produced an answer? | Langfuse traces from ADR-0010. | | What should be used for tenant billing and compliance reports? | Postgres `llm_calls`, `llm_pricing`, `api_request_logs`, and audit tables. | | What should be used for interactive debugging of one LLM answer? | Langfuse trace, linked from logs/Postgres by ids. | Logs may contain `request_id`, `run_id`, and `langfuse_trace_id` so engineers can navigate across all three systems. ## Consequences ### Positive - Logs become queryable by `request_id`, `thread_id`, `run_id`, `tenant_id`, `file_id`, and `ingestion_job_id`. - Contextvars prevent async task interleaving from mixing request context. - Stdlib/framework logs and application logs share one JSON structure. - Production logs are compatible with common log collectors and container runtimes. - Logs, Postgres audit rows, and Langfuse traces can be correlated without duplicating each system's purpose. ### Negative - Logging setup is more complex than plain `logging.basicConfig()`. - Developers must learn to use structured fields instead of prose-only log messages. - Context must be rebound at worker/background-task boundaries. - Too much logging can increase cost and leak sensitive data if redaction rules are not followed. - JSON logs are less pleasant locally unless a console renderer is enabled for development. ## Alternatives Considered - **Use Python stdlib logging only**: rejected. Stdlib logging can work, but `structlog` gives cleaner structured context, contextvars integration, and consistent event dictionaries across application and framework logs. - **Use manual `ContextVar` fields only**: rejected as the default. Manual context variables work, but `structlog.contextvars.bind_contextvars()` and `merge_contextvars` provide a standard way to bind arbitrary request fields without maintaining one `ContextVar` per field. Manual `ContextVar`s may still be used for special cases. - **Use `session_id` as the primary chat correlation field**: rejected for this service. ADR-0007 standardizes on `thread_id`, which maps to LangGraph threads and Langfuse sessions. If the main backend calls the same concept a session, it is translated to `thread_id` at this service boundary. - **Write only to `logs/app.log`**: rejected for production. File logging is useful locally, but stdout JSON is the better default for deployed services. - **Use Langfuse for all observability**: rejected. Langfuse is excellent for LLM/agent traces, prompt versions, scores, and evals, but it is not a replacement for process logs covering FastAPI middleware, auth, SQLAlchemy, Qdrant calls, worker lifecycle, and non-LLM failures. - **Use Postgres audit tables as logs**: rejected. ADR-0009 tables are durable business/audit records. They should not receive high-volume operational debug logs.