# 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 Production logs are JSON on stdout so process managers, container runtimes, and log collectors can ingest them directly. Local development may use a colored console renderer controlled by configuration. File logging is optional and mainly for local development. If enabled, it must use explicit rotation settings such as `maxBytes` and `backupCount`. Do not rely on a default `RotatingFileHandler` with no rotation parameters. In containerized production, stdout/stderr collection is preferred over writing `logs/app.log` inside the application container. ### 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 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.