chatbot_v3/docs/adr/0011-python-structured-logging-with-structlog.md

# 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.