Logging, metrics and health checks

On your laptop you find bugs by reading the terminal and adding print(). In production the API runs on a server you can't see, handles many requests at once, and the bug report says only "the app was slow at 9 pm". Observability means your API tells you what it is doing, so you can answer "what happened?" without guessing.

What you'll build: the Brew & Bean API (from *Build an API with Python and FastAPI*) with three additions. JSON logs with a request ID on every line, a /metrics endpoint that counts requests and measures how long they take, and /healthz and /readyz endpoints that a hosting platform can call to check the app.

Prerequisites: Python 3.10 or newer, basic FastAPI (routes, running with uvicorn) and a terminal with curl. Dashboards and alerts on top of these signals are covered in *Monitoring, logs and alerts* in the Cloud & DevOps track.

A fourth signal, tracing, follows one request across several services (API, then payment service, then database). You'll meet it with OpenTelemetry once you have more than one service. For a single API, good logs and metrics cover most problems.

A plain log line like Order failed for Rahul is easy for you to read but hard to search when there are a million of them. A structured log line is JSON with named fields: {"level": "ERROR", "message": "order failed", "order_id": 42}. Log tools (Grafana Loki, CloudWatch, Render's log view, plain grep with jq) can then filter by any field, for example "all lines where status is 500".

Python's built-in logging module only needs a custom formatter to print JSON. No extra library is needed.

import json
import logging
import sys
from datetime import datetime, timezone


class JsonFormatter(logging.Formatter):
    def format(self, record):
        entry = {
            "time": datetime.now(timezone.utc).isoformat(timespec="milliseconds"),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        # Extra fields passed with logger.info("...", extra={"fields": {...}})
        entry.update(getattr(record, "fields", {}))
        if record.exc_info:
            entry["error"] = self.formatException(record.exc_info)
        return json.dumps(entry)


def setup_logging(level="INFO"):
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())
    root = logging.getLogger()
    root.handlers = [handler]
    root.setLevel(level)
    # uvicorn prints its own access line per request; ours is richer, so silence it
    logging.getLogger("uvicorn.access").disabled = True

Every log record becomes one line of JSON on standard output. Logging to stdout (not to a file) is the convention for containers and cloud platforms: they collect stdout for you.

When 50 requests run at the same time, their log lines interleave. A request ID is a short random string attached to every line logged during one request, so you can pull out exactly that request's story. If the caller (a frontend or another service) already sent an X-Request-ID header, reuse it so the ID follows the request across systems. Return it in the response too: when a user reports an error, they (or your frontend) can quote the ID.

A FastAPI middleware wraps every request, which makes it the right place to time the request, catch unexpected errors and write one access log line. The same middleware will also record metrics in Step 3, so the full file below already includes them.

import logging
import os
import time
import uuid

from fastapi import FastAPI, HTTPException, Request
from fastapi.responses import JSONResponse
from prometheus_client import Counter, Histogram, make_asgi_app
from sqlalchemy import create_engine, text

from app.logging_setup import setup_logging

setup_logging(os.getenv("LOG_LEVEL", "INFO"))
logger = logging.getLogger("brewbean")

engine = create_engine(os.getenv("DATABASE_URL", "sqlite:///./brewbean.db"))

app = FastAPI(title="Brew & Bean API")

REQUESTS = Counter(
    "http_requests_total", "Total HTTP requests", ["method", "route", "status"]
)
LATENCY = Histogram(
    "http_request_duration_seconds", "Request duration in seconds", ["method", "route"]
)

# /metrics is served by prometheus_client
app.mount("/metrics", make_asgi_app())

MENU = [
    {"id": "espresso", "name": "Espresso", "category": "coffee", "price": 120},
    {"id": "masala-chai", "name": "Masala Chai", "category": "tea", "price": 90},
]


@app.middleware("http")
async def log_requests(request: Request, call_next):
    request_id = request.headers.get("X-Request-ID") or uuid.uuid4().hex[:12]
    request.state.request_id = request_id
    start = time.perf_counter()
    try:
        response = await call_next(request)
    except Exception:
        logger.exception("unhandled error", extra={"fields": {"request_id": request_id}})
        response = JSONResponse({"detail": "Internal server error"}, status_code=500)
    duration = time.perf_counter() - start

    # Use the route template (/orders/{order_id}), not the raw path (/orders/42)
    route = request.scope.get("route")
    route_path = route.path if route else "unmatched"
    if not request.url.path.startswith("/metrics"):
        REQUESTS.labels(request.method, route_path, str(response.status_code)).inc()
        LATENCY.labels(request.method, route_path).observe(duration)

    logger.info(
        "request",
        extra={"fields": {
            "request_id": request_id,
            "method": request.method,
            "path": request.url.path,
            "status": response.status_code,
            "duration_ms": round(duration * 1000, 1),
        }},
    )
    response.headers["X-Request-ID"] = request_id
    return response


@app.get("/menu")
def get_menu():
    return MENU


@app.get("/orders/{order_id}")
def get_order(order_id: int):
    if order_id != 1:
        raise HTTPException(status_code=404, detail="Order not found")
    return {"id": 1, "status": "preparing"}


@app.get("/boom")
def boom():
    raise RuntimeError("something broke")


@app.get("/healthz")
def liveness():
    return {"status": "ok"}


@app.get("/readyz")
def readiness():
    try:
        with engine.connect() as conn:
            conn.execute(text("SELECT 1"))
    except Exception:
        logger.exception("readiness check failed")
        return JSONResponse({"status": "unavailable", "database": "down"}, status_code=503)
    return {"status": "ok", "database": "up"}

The menu and order routes are tiny stand-ins so the file runs on its own; in your real project keep your existing routes and add the middleware, metrics and health routes. /boom exists only to demonstrate an unhandled error: delete it after this lesson.

Why each piece is there:

logger.exception(...) logs at ERROR level and includes the full traceback, so the bug's line number lands in your logs. The client only gets a plain "Internal server error": never send a traceback to the caller, because it reveals file paths and library versions to attackers.

time.perf_counter() is a clock meant for measuring durations. time.time() can jump if the server's clock is adjusted.

HTTPException (the 404) is a normal, handled response, so it does not reach the except block. Only real crashes do.

uvicorn app.main:app --port 8000

# in a second terminal
curl -i http://localhost:8000/menu
curl -i http://localhost:8000/orders/7
curl -i http://localhost:8000/boom
curl -i -H "X-Request-ID: abc123" http://localhost:8000/menu

On Windows, use curl.exe in PowerShell so you get the real curl rather than the PowerShell alias.

Notice the ERROR line and the access line for /boom share the same request_id. With real traffic you would search for 2ba61036fb9f and see only that request's lines. The few plain-text lines uvicorn prints at startup ("Uvicorn running on...") come from its own logger setup; that's fine.

To log a business event inside a route, pass extra fields the same way, for example after saving an order: logger.info("order created", extra={"fields": {"order_id": order.id, "total": order.total}}).

Logs describe single requests. Metrics are numbers aggregated over time, cheap to store and easy to graph and alert on. Prometheus is the most common open-source metrics system: your app exposes current numbers as text at /metrics, and a Prometheus server fetches ("scrapes") that page every few seconds and stores the history.

The middleware above already records two metrics:

A Counter (http_requests_total) only goes up. From it Prometheus computes request rate and error rate (requests with status 5xx divided by all requests).

A Histogram (http_request_duration_seconds) puts each duration into buckets, so you can ask for percentiles such as p95: the time under which 95% of requests finish. Averages hide slow requests; p95 and p99 show what your unluckiest users feel.

curl -s http://localhost:8000/metrics/ | grep http_requests_total

Note the trailing slash: the metrics app is mounted, so /metrics answers with a 307 redirect to /metrics/. Use curl -L or the slash.

The thresholds above are starting points to tune, not rules. Choose them from what your users notice. Prometheus queries (PromQL), Grafana dashboards and alert routing are covered in the DevOps track; for an interview, being able to name these four signals and say why you measure p95 instead of the average is already a strong answer.

Platforms like Kubernetes, Render, AWS load balancers and Docker call a URL on your app every few seconds to decide what to do with it. There are two different questions, so use two endpoints.

Liveness (/healthz): is the process alive and able to answer at all? If this fails repeatedly, the platform restarts the app. Keep it trivial; don't check the database here. Otherwise a short database outage makes the platform restart every API instance in a loop, which makes things worse.

Readiness (/readyz): can this instance serve real traffic right now? It checks the dependencies the app can't work without (here, the database with SELECT 1). If it fails, the platform stops sending traffic to this instance but doesn't restart it. It returns 503 Service Unavailable, the status code that means "temporarily can't serve".

You are a senior backend engineer helping me debug a production issue.

Stack: [FastAPI / Express / other], database: [PostgreSQL / SQLite / MongoDB], hosted on [platform].
Symptom: [what users saw, e.g. 500 errors on POST /orders since 9 pm].

Here are the log lines for one failing request (I removed personal data):
---
[paste JSON log lines with the same request_id]
---

1. Explain in plain English what happened, in order.
2. Give the most likely root cause and how confident you are.
3. Tell me what extra log field or metric would have made this easier to diagnose.

What to expect: A good answer walks through the lines in time order, points at the specific line and field that shows the cause, and separates what the logs prove from what it is guessing. Remove names, phones and tokens before pasting.