Skip to main content

Module 8 — Logging and health probes

The service now scores subscribers, refuses bad input, protects itself with a token and offloads long jobs. It still lacks the observability that turns "the model returned 0.83 to the wrong subscriber at 14:07" into a two-minute investigation. This module adds three things that pay for themselves in the first incident: structured logs with a request ID, two health probes the orchestrator can distinguish, and the first useful metrics on latency and errors. Prometheus is previewed at the end.

Why structured logs, not print​

A print("scoring", subscriber_id, probability) line is human-readable and machine-hostile. It cannot be filtered, aggregated, or joined to anything else. A modern log aggregator (Datadog, Loki, CloudWatch Logs Insights) wants one JSON object per line, with typed fields: timestamp, level, message, and any relevant context. The two payoffs are that the aggregator indexes those fields, so a query like service:churn AND status:500 AND request_id:abc returns in milliseconds, and that dashboards and alerts can be built without a regex ever entering the picture.

The stdlib's logging module produces JSON with a small formatter:

# app/logging_setup.py
import json, logging, sys, time


class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(record.created)),
            "level": record.levelname,
            "logger": record.name,
            "message": record.getMessage(),
        }
        # Carry any 'extra' fields (request_id, latency_ms, ...) verbatim.
        for k, v in record.__dict__.items():
            if k in ("args", "msg", "levelname", "levelno", "created",
                     "msecs", "name", "pathname", "filename", "module",
                     "exc_info", "exc_text", "stack_info", "lineno",
                     "funcName", "processName", "process", "thread", "threadName"):
                continue
            payload[k] = v
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        return json.dumps(payload, ensure_ascii=False)


def setup_logging(level: int = logging.INFO) -> None:
    handler = logging.StreamHandler(sys.stdout)
    handler.setFormatter(JsonFormatter())
    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(handler)
    root.setLevel(level)

Then in the application:

# app/main.py (continued)
import logging
from app.logging_setup import setup_logging

setup_logging()
logger = logging.getLogger("churn")

logger.info("startup complete", extra={"model_uri": "models:/churn-classifier@production"})

The extra argument attaches typed fields to the log line without weaving them into the message string. That is what makes filtering possible: extra.model_uri:"models:/churn-classifier@production" is a legal, indexed query.

The request ID middleware​

Every log line worth reading is scoped to a request. A request ID middleware generates a UUID (or reuses one the caller provided) and attaches it to both the request state and to every log line emitted during the request:

# app/middleware.py
import uuid, time, logging
from starlette.middleware.base import BaseHTTPMiddleware
from starlette.requests import Request

logger = logging.getLogger("churn.access")


class RequestIdMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next):
        rid = request.headers.get("X-Request-ID", str(uuid.uuid4()))
        request.state.request_id = rid
        start = time.perf_counter()
        response = await call_next(request)
        latency_ms = round((time.perf_counter() - start) * 1000, 2)
        response.headers["X-Request-ID"] = rid
        logger.info(
            "request",
            extra={
                "request_id": rid,
                "method": request.method,
                "path": request.url.path,
                "status": response.status_code,
                "latency_ms": latency_ms,
            },
        )
        return response

Register it on the app:

from app.middleware import RequestIdMiddleware
app.add_middleware(RequestIdMiddleware)

Two properties are worth naming. The middleware echoes X-Request-ID back in the response, so a caller can quote the ID in a support ticket and it will match a server log line. And latency is measured around the whole call, including the auth dependency and the JSON serialization — the client's experience, not just the model's inference time.

Never log PII, never log raw payloads​

A subscriber ID that is a hashed opaque token is fine to log. A subscriber's email, name, phone number, or contract details are PII and belong in the log only if you have a very specific reason and a retention policy that matches. The default posture is:

  • Log the request ID, the path, the status, the latency, the caller name, the model version.
  • Do not log the request body. Not even at DEBUG. logger.debug("body=%s", body) in a dev environment ends up in dev logs, and dev logs end up shared.
  • Redact tokens even in error messages: Authorization: Bearer *** if you must mention them at all.

Liveness and readiness are different probes​

Kubernetes, ECS, and every serious orchestrator distinguish two health signals:

  • Liveness answers "is this process alive?" If it returns non-2xx, the orchestrator restarts the container.
  • Readiness answers "is this process ready to serve traffic?" If it returns non-2xx, the orchestrator stops routing to it but does not restart it.

A single /health endpoint that mixes both is the most common misconfiguration in ML services. The classic failure mode: the model reload during a swap makes /health return 503 for 20 seconds, the orchestrator concludes the process is dead, restarts it, and the reload runs again — a restart loop.

Two endpoints, two contracts:

# app/main.py (continued)
from fastapi import FastAPI, status

from app.state import MODEL_STATE

app = FastAPI(title="Churn scoring API", version="0.8.0")


@app.get("/healthz", tags=["meta"])
def liveness() -> dict:
    # Alive means: the Python process is running and the event loop is
    # responsive. Do not touch the model, the DB, or the network here.
    return {"status": "alive"}


@app.get("/ready", tags=["meta"])
def readiness(response) -> dict:
    if "model" not in MODEL_STATE:
        response.status_code = status.HTTP_503_SERVICE_UNAVAILABLE
        return {"status": "loading_model"}
    return {"status": "ready", "model_version": MODEL_STATE["version"]}

The two probes now behave the way the orchestrator expects. Liveness stays green as long as the process is up — nothing else can hang it. Readiness swings to 503 during a model load, keeps the pod out of the load balancer, and swings back to 200 when the load completes. A rolling deploy never sends traffic to a pod that is still warming up.

Metrics: the two ratios that always matter​

Two ratios summarize the health of an ML API in production:

  • Latency percentiles, especially p50, p95 and p99. A p50 that doubles overnight is a data drift alarm; a p99 that lags a p50 that stays flat is a saturation alarm.
  • Error ratios, split by class: 4xx (client), 5xx (server). A quiet 5xx rate is nominal; any 4xx spike is worth explaining, not silencing.

The middleware above already logs latency_ms and status per request, so both ratios can be computed from logs alone by the aggregator. That is the cheapest starting point.

Prometheus in one sketch​

The next step, when the volume warrants it, is a /metrics endpoint that exposes counters and histograms in the Prometheus text format. prometheus-fastapi-instrumentator gives it in three lines:

# app/metrics.py — preview only
from prometheus_fastapi_instrumentator import Instrumentator

def setup_metrics(app):
    Instrumentator(should_group_status_codes=True).instrument(app).expose(app, endpoint="/metrics")

Grafana panels then plot histogram_quantile(0.95, sum by (le) (rate(http_request_duration_seconds_bucket{service="churn"}[5m]))) and the p95 becomes a first-class alert target. This is the shape covered end-to-end in the MLOps course; this module wires the plumbing FastAPI-side so that the metrics scrape is answered correctly.

Sample INFO logs above one request per second

An ML service that serves 500 requests per second and logs one INFO line per request writes 43 million lines per day. That is expensive to store and slow to search. Either drop to WARN by default and turn on INFO on demand, or sample INFO (if random.random() < 0.1) with a sticky bit on the request ID so a support ticket that quotes an ID can still find its line.

In summary​

  • Emit JSON logs through the stdlib logging module with a small JsonFormatter; attach fields with extra, not with the message string.
  • Add a request-ID middleware that echoes X-Request-ID and logs method, path, status and latency_ms per request. Never log the body or any PII.
  • Expose two probes: /healthz is liveness (never restarts on a failing model), /ready is readiness (503 during load, stops traffic).
  • Track latency percentiles and error ratios; expose /metrics in Prometheus format when volume justifies it, and alert on p95, not on averages.

Next module: containerization and deployment — packaging everything from modules 1 to 8 into a small, non-root image and running multiple workers behind a load balancer.