Drills: Observability

import structlog

structlog.configure(
    processors=[
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.processors.JSONRenderer(),
    ],
)
log = structlog.get_logger()
log.info("ask_started", doc_id="d_12", q_len=42)
# {"doc_id": "d_12", "q_len": 42, "event": "ask_started", "level": "info", ...}

import logging, structlog

structlog.configure(
    wrapper_class=structlog.make_filtering_bound_logger(logging.INFO),
)
log = structlog.get_logger()
log.debug("noisy_detail")     # suppressed (below INFO)
log.info("request_done")     # shown
log.warning("retried_llm")     # shown
log.error("call_failed")      # shown

In prod you run at INFO; flip to DEBUG only while investigating one service.

from prometheus_client import Counter, generate_latest

ASKS = Counter("ask_requests_total", "Total /ask calls", ["status"])
ASKS.labels("ok").inc()
ASKS.labels("error").inc()

print(generate_latest().decode())
# ask_requests_total{status="ok"} 1.0
# ask_requests_total{status="error"} 1.0

import uuid
from structlog.contextvars import bind_contextvars, clear_contextvars
from starlette.middleware.base import BaseHTTPMiddleware

class RequestIdMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        clear_contextvars()
        rid = request.headers.get("x-request-id") or uuid.uuid4().hex[:12]
        bind_contextvars(request_id=rid, path=request.url.path)
        response = await call_next(request)
        response.headers["x-request-id"] = rid
        return response

app.add_middleware(RequestIdMiddleware)

Every log emitted inside the request now carries request_id for free — the foundation of "follow one request".

import sentry_sdk

try:
    answer = run_ask(question, doc_id)
except Exception as e:
    with sentry_sdk.new_scope() as scope:
        scope.set_tag("feature", "ask")
        scope.set_context("ask", {"doc_id": doc_id})
        scope.set_user({"id": user_id})
        sentry_sdk.capture_exception(e)
    raise

Context is what turns "something broke" into "this broke, for this user, on this doc" — reproducible.

from opentelemetry import trace

tracer = trace.get_tracer("docchat")

with tracer.start_as_current_span("llm.chat") as span:
    span.set_attribute("llm.model", "claude")
    resp = call_llm(prompt)                 # the work being measured
    span.set_attribute("llm.prompt_tokens", resp.usage.input_tokens)
    span.set_attribute("llm.completion_tokens", resp.usage.output_tokens)

The span shows up as a child of the auto-instrumented request span — now you can see exactly how long the LLM took inside the whole request.

import time
from opentelemetry import trace
from prometheus_client import Counter
from app.logging import log

tracer = trace.get_tracer("docchat")
LLM_COST = Counter("llm_cost_usd_total", "LLM spend", ["model"])

@router.post("/ask")
async def ask(body: AskIn, user=Depends(current_user)):
    with tracer.start_as_current_span("ask") as root:
        root.set_attribute("doc_id", body.doc_id)

        with tracer.start_as_current_span("retrieval") as rspan:
            chunks = await retrieve(body.doc_id, body.question, k=5)
            rspan.set_attribute("chunks", len(chunks))

        with tracer.start_as_current_span("llm.chat") as lspan:
            t0 = time.perf_counter()
            resp = await client.messages.create(
                model=MODEL, max_tokens=1024,
                messages=build_prompt(chunks, body.question),
            )
            seconds = time.perf_counter() - t0
            in_tok, out_tok = resp.usage.input_tokens, resp.usage.output_tokens
            cost = price(MODEL, in_tok, out_tok)
            lspan.set_attribute("llm.cost_usd", cost)

        LLM_COST.labels(MODEL).inc(cost)             # first-class cost metric
        log.info("ask_completed", model=MODEL,
                 prompt_tokens=in_tok, completion_tokens=out_tok,
                 cost_usd=round(cost, 5), llm_seconds=round(seconds, 2))
        return {"answer": resp.content[0].text}

Note the shape: a root span with two children, a counter incremented by real dollars, and one log line that makes a single request's cost and latency queryable. Tracing tells you where the time went; the cost metric and log tell you what it cost.