Errors and observability¶
An orders API that is easy to operate. Its errors are RFC 9457 problem details, from
FastAPIProblemDetails: a validation error says where and what
without echoing what was sent, running out of stock is a Problem
with an available member, and a bug is a bare 500 that tells the client nothing about it.
RequestIDMiddleware gives every request an ID, which RequestIDLogFilter
puts in every log line, uvicorn's included, and which comes back in a header and in every problem.
RequestTimeoutMiddleware gives every request a deadline: the slow
sales report gets a 504 and its database connection back, while the CSV export streams for as long
as it takes. health_router adds the probes of the load balancer,
with the database as a critical check and the cache as a non-critical one. OpenTelemetry needs no
code: under its zero-code instrumentation, Alcazaba's metrics and spans go out with the app's
(Metrics and traces).
Run it¶
From a clone of the repository:
make deps # .venv, with every extra
source .venv/bin/activate
python examples/observability/main.py
That starts uvicorn with the example's LOGGING configuration, so that every log line carries the
request's ID. uvicorn examples.observability.main:app serves the same app with uvicorn's
default logging, without the IDs; to use the configuration with the uvicorn command, save it as
JSON and pass --log-config.
Try it¶
An order placed. The response has an X-Request-ID, and so does every line logged for it:
$ curl -i -X POST http://127.0.0.1:8000/orders -H "Content-Type: application/json" \
-d '{"product_id": 1, "quantity": 2}'
HTTP/1.1 201 Created
content-type: application/json
x-request-id: efdd515c85e68aefadfe379f34142eef
{"product_id":1,"quantity":2,"id":31}
2026-10-26 12:34:23,679 INFO [efdd515c85e68aefadfe379f34142eef] orders: Order 31 placed
2026-10-26 12:34:23,680 INFO [efdd515c85e68aefadfe379f34142eef] "POST /orders HTTP/1.1" 201 Created
A validation error says which field is wrong and why, but not what was sent: FastAPI's own answer would echo the input, passwords included.
$ curl -i -X POST http://127.0.0.1:8000/orders -H "Content-Type: application/json" \
-d '{"product_id": 1, "quantity": "lots"}'
HTTP/1.1 422 Unprocessable Content
x-request-id: f25fd411982ef2db845915fd6c6591b6
content-type: application/problem+json
{"type":"about:blank","title":"Unprocessable Content","status":422,"instance":"/orders","errors":[{"loc":["body","quantity"],"msg":"Input should be a valid integer, unable to parse string as an integer","type":"int_parsing"}],"request_id":"f25fd411982ef2db845915fd6c6591b6"}
Running out of stock is a problem of the API's own, with its type and an available member that
a client can act on:
$ curl -i -X POST http://127.0.0.1:8000/orders -H "Content-Type: application/json" \
-d '{"product_id": 2, "quantity": 5}'
HTTP/1.1 409 Conflict
x-request-id: 3905c40b8fa0c37707adf6b910773f47
content-type: application/problem+json
{"type":"https://example.com/problems/out-of-stock","title":"Out of stock","status":409,"detail":"Only 3 left","instance":"/orders","available":3,"request_id":"3905c40b8fa0c37707adf6b910773f47"}
A bug: the invoice's PDF renderer refuses the connection, and nothing handles it. The client gets a bare 500 with nothing about the renderer, and the request ID to quote. Here the client sent the ID itself, as a proxy would, and it was kept:
$ curl -i http://127.0.0.1:8000/orders/3/invoice -H "X-Request-ID: support-ticket-4512"
HTTP/1.1 500 Internal Server Error
x-request-id: support-ticket-4512
content-type: application/problem+json
{"type":"about:blank","title":"Internal Server Error","status":500,"instance":"/orders/3/invoice","request_id":"support-ticket-4512"}
The server logs the traceback under that ID:
2026-10-26 12:34:23,692 INFO [support-ticket-4512] "GET /orders/3/invoice HTTP/1.1" 500 Internal Server Error
2026-10-26 12:34:23,692 ERROR [support-ticket-4512] uvicorn.error: Exception in ASGI application
Traceback (most recent call last):
...
File ".../examples/observability/main.py", line 140, in invoice
raise ConnectionError(f"pdf-renderer.internal:9000 refused the invoice of order {order_id}")
ConnectionError: pdf-renderer.internal:9000 refused the invoice of order 3
The sales report takes 30 s. At the 10 s deadline the query is cancelled, its connection goes back
to the pool and the client gets a 504. The middleware answers it itself, and with
FastAPIProblemDetails installed its answer is a problem too:
$ curl -i http://127.0.0.1:8000/reports/sales
HTTP/1.1 504 Gateway Timeout
x-request-id: 7ec602139e1478ad0c023637123c599e
content-type: application/problem+json
{"type":"about:blank","title":"Gateway Timeout","status":504,"detail":"Request timed out","instance":"/reports/sales","request_id":"7ec602139e1478ad0c023637123c599e"}
2026-10-26 15:22:34,756 WARNING [7ec602139e1478ad0c023637123c599e] fastapi_alcazaba.observability.timeouts: GET /reports/sales timed out after 10.0s: answered 504
The export has no deadline: its 30 rows stream for 15 s, and it isn't cut short.
$ curl -s -o /dev/null -w '%{http_code} %{content_type} %{size_download} bytes in %{time_total}s\n' \
http://127.0.0.1:8000/orders/export
200 text/csv; charset=utf-8 231 bytes in 15.539356s
The probes. Readiness runs the checks and says how each went; liveness only says that the process answers:
$ curl -i http://127.0.0.1:8000/health/ready
HTTP/1.1 200 OK
cache-control: no-store
content-type: application/json
x-request-id: 577fa3fd67c00a6bd4b80cbf29256384
{"status":"ok","checks":{"database":{"status":"ok","duration_ms":0.014},"cache":{"status":"ok","duration_ms":0.012}}}
$ curl http://127.0.0.1:8000/health/live
{"status":"ok"}
What to look at¶
- The order of the middlewares: the last one added is the outermost.
RequestIDMiddlewaregoes around the deadline, so that the 504 has an ID too. A 500 is answered outside every middleware, by Starlette, andFastAPIProblemDetailsadds the ID to it itself. - The filter on the handlers: a logger's filters don't see the records of its children, so
RequestIDLogFiltergoes on both handlers of the logging configuration, and uvicorn's access and error lines get the ID along with the app's. - Nothing to learn from an error: validation errors never carry the input, the 500 says
nothing about the renderer, and the database's
db.internal:5432: connection refusedwould be logged by the readiness check, never returned to a public probe. - A deadline gives resources back: the connection is a
yielddependency, so it goes back to the pool when the deadline cancels the request. The export is exempt (paths={"/orders/export": None}): once a response has started it can't become a 504, it would only be cut short. - Critical or not: a failing database makes
/health/readya 503 and takes the process out of the load balancer; a failing cache only makes itdegraded, since the cache fails open and taking every process out would turn its outage into a full one. - OpenTelemetry without code: run the app under
opentelemetry-instrument. The FastAPI instrumentation traces each request, and Alcazaba's metrics (fastapi_alcazaba.problems,.request_timeouts,.request_ids,.health.checks…) go out through the same SDK.
The code¶
examples/observability/main.py
"""An orders API that is easy to operate: errors, request IDs, deadlines and health checks.
python examples/observability/main.py # uvicorn, with the logging configuration below
- Errors are RFC 9457 problem details (`application/problem+json`): a validation error says where
and what, never the values sent; running out of stock is a `Problem` with an `available`
member; a bug is a bare 500 that tells the client nothing about it.
- Every request has an ID, in the `X-Request-ID` response header, in every problem and in every
log line, uvicorn's included: a client quotes it, and its lines are found in the logs.
- Every request has a deadline: the slow sales report gets a 504 and its database connection
back, while the CSV export streams for as long as it takes.
- `/health/live` and `/health/ready` for the load balancer: the database is a critical check, the
cache a non-critical one.
OpenTelemetry needs nothing here. Run the app under its zero-code instrumentation
(`opentelemetry-instrument`, see "Metrics and traces" in the guide): the FastAPI instrumentation
traces each request, and Alcazaba's metrics (problems, request_timeouts, request_ids,
health.checks...) go out through the meter of the app's cache.
"""
import asyncio
import logging
from collections.abc import AsyncIterator
from contextlib import asynccontextmanager
from typing import Annotated, Any
import uvicorn
from fastapi import APIRouter, Depends, FastAPI, HTTPException, Request, status
from fastapi.responses import StreamingResponse
from pydantic import BaseModel, Field
from fastapi_alcazaba import Cache, FastAPIProblemDetails, Problem
from fastapi_alcazaba.backends.inmemory import InMemoryBackend
from fastapi_alcazaba.observability import (
RequestIDMiddleware,
RequestTimeoutMiddleware,
health_router,
)
logger = logging.getLogger("orders")
LOG_FORMAT = "%(asctime)s %(levelname)s [%(request_id)s] %(name)s: %(message)s"
ACCESS_FORMAT = '%(asctime)s %(levelname)s [%(request_id)s] "%(request_line)s" %(status_code)s'
# uvicorn's log_config. The filter goes on every handler (a logger's filters don't see the records
# of its children), so uvicorn's access and error lines carry the ID too. Plain JSON: for the
# uvicorn command, save it to a file and pass --log-config.
LOGGING: dict[str, Any] = {
"version": 1,
"disable_existing_loggers": False,
"filters": {
"request_id": {"()": "fastapi_alcazaba.observability.RequestIDLogFilter"},
},
"formatters": {
"default": {"format": LOG_FORMAT},
"access": {"()": "uvicorn.logging.AccessFormatter", "fmt": ACCESS_FORMAT},
},
"handlers": {
name: {
"class": "logging.StreamHandler",
"formatter": name,
"filters": ["request_id"],
}
for name in ("default", "access")
},
"loggers": {
"uvicorn.access": {"handlers": ["access"], "level": "INFO", "propagate": False},
},
"root": {"handlers": ["default"], "level": "INFO"},
}
class NewOrder(BaseModel):
product_id: int = Field(gt=0)
quantity: int = Field(gt=0, le=100)
class Order(NewOrder):
id: int
class Database:
"""Stands in for the database and its connection pool."""
def __init__(self) -> None:
self.stock = {1: 25, 2: 3} # units left, by product
self.orders = [Order(id=n, product_id=1, quantity=1) for n in range(1, 31)]
self.in_use = 0 # connections taken from the pool
self.up = True
self.report_seconds = 30.0 # the sales report is a slow query
self.row_seconds = 0.5 # and the export reads its rows slowly
async def ping(self) -> None:
if not self.up:
# What drivers say: a host and a port that a public probe mustn't show anyone.
raise ConnectionRefusedError("db.internal:5432: connection refused")
async def connection(request: Request) -> AsyncIterator[Database]:
"""A connection from the pool, given back when the request ends, also when it times out."""
db: Database = request.app.state.db
db.in_use += 1
try:
yield db
finally:
db.in_use -= 1
DB = Annotated[Database, Depends(connection)]
router = APIRouter()
@router.post("/orders", status_code=status.HTTP_201_CREATED)
async def place_order(new: NewOrder, db: DB) -> Order:
if new.product_id not in db.stock:
raise HTTPException(
status.HTTP_404_NOT_FOUND,
"No such product",
) # a 4xx's detail is sent
available = db.stock[new.product_id]
if new.quantity > available:
raise Problem(
status.HTTP_409_CONFLICT,
f"Only {available} left",
type="https://example.com/problems/out-of-stock",
title="Out of stock",
extensions={"available": available},
)
db.stock[new.product_id] -= new.quantity
order = Order(id=len(db.orders) + 1, **new.model_dump())
db.orders.append(order)
logger.info("Order %d placed", order.id) # the filter adds the request's ID
return order
@router.get("/orders/export")
async def export_orders(db: DB) -> StreamingResponse:
"""Every order as CSV, sent as the rows are read. It has no deadline (see `paths` below): once
a response has started it can't become a 504, it would only be cut short."""
async def rows() -> AsyncIterator[str]:
yield "id,product_id,quantity\n"
for order in list(db.orders):
await asyncio.sleep(db.row_seconds)
yield f"{order.id},{order.product_id},{order.quantity}\n"
return StreamingResponse(rows(), media_type="text/csv")
@router.get("/orders/{order_id}/invoice")
async def invoice(order_id: int) -> dict[str, str]:
"""A failure nobody handled: the client gets a bare 500 with the request ID to quote, and the
server logs the traceback under that ID."""
raise ConnectionError(f"pdf-renderer.internal:9000 refused the invoice of order {order_id}")
@router.get("/reports/sales")
async def sales_report(db: DB) -> dict[str, int]:
"""At the deadline the query is cancelled, the connection goes back to the pool and the
client gets a 504, instead of both waiting for as long as the query takes."""
await asyncio.sleep(db.report_seconds)
return {"orders": len(db.orders)}
@asynccontextmanager
async def lifespan(application: FastAPI) -> AsyncIterator[None]:
application.state.db = Database()
yield
def create_app(*, request_timeout: float = 10.0) -> FastAPI:
"""The application, with a deadline of `request_timeout` seconds per request."""
application = FastAPI(lifespan=lifespan)
# In memory: nothing but this process reads or writes it. Alcazaba's metrics are recorded
# through it, and /health/ready checks it.
Cache(InMemoryBackend(), prefix="orders").install(application)
FastAPIProblemDetails().install(application)
application.include_router(router)
async def database() -> None:
await application.state.db.ping()
application.include_router(health_router({"database": database}))
# The last middleware added is the outermost. RequestIDMiddleware goes around the deadline, so
# that the 504 it answers carries the ID too. (A 500 is answered outside every middleware;
# FastAPIProblemDetails adds the ID to it itself.)
application.add_middleware(
RequestTimeoutMiddleware,
timeout=request_timeout,
paths={"/orders/export": None},
)
# Keeps a safe X-Request-ID set by the proxy (or the client); trust_incoming=False if clients
# reach the application directly and shouldn't choose their IDs.
application.add_middleware(RequestIDMiddleware)
return application
app = create_app()
if __name__ == "__main__":
uvicorn.run("main:app", reload=True, log_config=LOGGING)