Logging, Metrics, and API Testing

A support ticket arrives: "the classifier gave a weird answer around 2pm yesterday." You open the logs. Eleven replicas have been writing lines like this all day:

2024-03-14 14:03:12 INFO Prediction made2024-03-14 14:03:12 INFO Processing request2024-03-14 14:03:13 INFO Prediction made2024-03-14 14:03:13 ERROR Something went wrong: list index out of range

There are 1.4 million such lines for that hour. Nothing identifies the user, the input, the model version, or which of the eleven replicas wrote each line. You cannot even tell whether the ERROR belongs to the same request as the INFO above it. Three hours later you give up and reply that you were unable to reproduce it.

The model was fine. The observability was not. An inference service that you cannot interrogate after the fact is a service you cannot operate, and the difference between the log above and one you can actually use is a couple of hours of work done up front.

Structured logging

The problem with the lines above is that they are prose. "Prediction made" is a sentence, and extracting anything from it requires a regular expression that breaks the moment someone rewords the message. Structured logging emits each event as a JSON object with named fields, so querying becomes filtering rather than parsing.

1import logging, json, time, uuid2from contextvars import ContextVar34request_id_var: ContextVar[str] = ContextVar("request_id", default="-")56class JsonFormatter(logging.Formatter):7    RESERVED = set(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | {"message", "asctime"}89    def format(self, record: logging.LogRecord) -> str:10        payload = {11            "ts": time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(record.created))12                  + f".{int(record.msecs):03d}Z",13            "level": record.levelname,14            "logger": record.name,15            "message": record.getMessage(),16            "request_id": request_id_var.get(),17            "service": "defect-api",18            "version": "2.5.0",19        }20        for key, value in record.__dict__.items():        # anything passed via extra=21            if key not in self.RESERVED:22                payload[key] = value23        if record.exc_info:24            payload["exception"] = self.formatException(record.exc_info)25        return json.dumps(payload, default=str)2627handler = logging.StreamHandler()28handler.setFormatter(JsonFormatter())29logging.basicConfig(level=logging.INFO, handlers=[handler])30log = logging.getLogger("serving")

Used like this:

1log.info("prediction", extra={2    "model_version": "2.5.0",3    "predicted_label": "scratch",4    "confidence": 0.9134,5    "latency_ms": 84.2,6    "input_bytes": 217_884,7    "user_id_hash": "a3f1c2",8})

1{"ts":"2024-03-14T14:03:12.417Z","level":"INFO","logger":"serving",2 "message":"prediction","request_id":"7c2e-4a91","service":"defect-api",3 "version":"2.5.0","model_version":"2.5.0","predicted_label":"scratch",4 "confidence":0.9134,"latency_ms":84.2,"input_bytes":217884,"user_id_hash":"a3f1c2"}

Now the ticket is answerable. In any log store, "show me predictions between 13:55 and 14:05 where confidence was below 0.6" is a filter expression, not a research project.

Correlation IDs

The second half of the fix is tying every line from one request together. A correlation ID is generated at the edge (or accepted from an upstream service), attached to the logging context, and returned to the client.

1from starlette.middleware.base import BaseHTTPMiddleware23class RequestContext(BaseHTTPMiddleware):4    async def dispatch(self, request, call_next):5        rid = request.headers.get("x-request-id") or uuid.uuid4().hex[:12]6        token = request_id_var.set(rid)7        started = time.perf_counter()8        try:9            response = await call_next(request)10            elapsed = (time.perf_counter() - started) * 100011            log.info("request", extra={12                "method": request.method, "path": request.url.path,13                "status": response.status_code, "duration_ms": round(elapsed, 2),14            })15            response.headers["x-request-id"] = rid16            return response17        finally:18            request_id_var.reset(token)1920app.add_middleware(RequestContext)

ContextVar is the right tool here rather than a global or a thread-local, because it is correct under both threading and asyncio — each task gets its own value automatically.

Returning the ID in the response header changes the support workflow completely: the user pastes the ID from their error message, you filter on it, and you have every log line for that exact request across every service it touched, in order.

The value of a log line is set by what you can filter on, not by how well it is worded.

What not to log

Two hard rules. Never log raw model inputs when they may contain personal data — log a hash, a shape, and a size instead. And never log at INFO inside a loop that runs per prediction element; a batch of 64 producing 64 log lines at 200 requests per second is 12,800 lines a second, which will cost more than your inference does.

Metrics: a different tool for a different question

Logs answer "what happened to this specific request". Metrics answer "what is happening in aggregate, right now". Trying to use one for the other is expensive in both directions.

The four Prometheus metric types

1from prometheus_client import Counter, Histogram, Gauge, Summary, make_asgi_app23REQUESTS = Counter(4    "inference_requests_total", "Total inference requests",5    ["model_version", "endpoint", "status"],6)7LATENCY = Histogram(8    "inference_duration_seconds", "Inference latency",9    ["model_version", "stage"],10    buckets=[0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0],11)12IN_FLIGHT = Gauge("inference_in_flight", "Requests currently being processed")13CONFIDENCE = Histogram(14    "prediction_confidence", "Confidence of the winning class",15    buckets=[0.1, 0.2, 0.3, 0.4, 0.5, 0.6, 0.7, 0.8, 0.9, 0.95, 0.99, 1.0],16)1718app.mount("/metrics", make_asgi_app())

Two things about this list are worth spelling out.

Choose histogram buckets deliberately. Buckets are the resolution of every latency question you will ever ask. If your p99 target is 200 ms and your buckets jump from 0.1 to 1.0, every answer will be "somewhere between 100 ms and 1 second", which is useless. Put several buckets around your SLO threshold.

Keep label cardinality low. Every distinct combination of label values creates a separate time series. ["model_version", "endpoint", "status"] with 3 versions, 4 endpoints and 5 statuses is 60 series — fine. Add user_id with a million users and you have a million series, which will take down your Prometheus server. This is the single most common way people break a metrics system.

Never put an unbounded value — user ID, request ID, raw input — in a metric label; that is what logs are for.

Instrumenting the handler

1@app.post("/predict")2def predict(req: PredictRequest):3    IN_FLIGHT.inc()4    status = "success"5    try:6        with LATENCY.labels("2.5.0", "preprocess").time():7            x = preprocess(req)8        with LATENCY.labels("2.5.0", "inference").time():9            probs = model(x)10        conf = float(probs.max())11        CONFIDENCE.observe(conf)12        return {"label": LABELS[int(probs.argmax())], "confidence": conf}13    except ValidationError:14        status = "client_error"; raise15    except Exception:16        status = "server_error"; raise17    finally:18        REQUESTS.labels("2.5.0", "/predict", status).inc()19        IN_FLIGHT.dec()

Timing the stages separately is what turns "it got slow" into "preprocessing got slow", which is a completely different investigation. The CONFIDENCE histogram is the ML-specific one and it is the most valuable: a shift in the confidence distribution is the earliest visible sign of data drift, and it needs no labels to detect. If the fraction of predictions above 0.9 falls from 71% to 44% over a week, the model is seeing inputs unlike its training data — long before your accuracy metrics catch up, because those need ground truth that arrives days later.

If you cannot run Prometheus

A ring buffer plus a JSON endpoint gets you most of the operational value in twenty lines:

1from collections import deque2import threading, statistics34class Stats:5    def __init__(self, maxlen=10_000):6        self.lat = deque(maxlen=maxlen)7        self.counts = {"success": 0, "client_error": 0, "server_error": 0}8        self.lock = threading.Lock()910    def record(self, ms, status):11        with self.lock:12            self.lat.append(ms)13            self.counts[status] = self.counts.get(status, 0) + 11415    def snapshot(self):16        with self.lock:17            values = sorted(self.lat)18            total = sum(self.counts.values())19        if not values:20            return {"requests": 0}21        def q(p): return values[min(int(len(values) * p), len(values) - 1)]22        return {"requests": total, "counts": dict(self.counts),23                "p50_ms": round(q(0.50), 1), "p95_ms": round(q(0.95), 1),24                "p99_ms": round(q(0.99), 1), "max_ms": round(values[-1], 1),25                "error_rate": round(1 - self.counts["success"] / total, 4)}2627STATS = Stats()2829@app.get("/stats")30def stats(): return STATS.snapshot()

Health checks: two questions, not one

Container orchestrators ask two distinct questions, and conflating them causes a specific and very common outage.

1@app.get("/healthz")            # liveness: cheap, no dependencies2def healthz():3    return {"status": "alive"}45@app.get("/readyz")             # readiness: is this replica actually useful?6def readyz():7    checks = {}8    checks["model_loaded"] = STATE.get("model") is not None9    try:10        with torch.no_grad():11            STATE["model"](STATE["warmup_tensor"])12        checks["model_runs"] = True13    except Exception as e:14        checks["model_runs"] = False15        log.error("readiness inference failed", extra={"error": str(e)})16    try:17        checks["feature_store"] = feature_store.ping(timeout=0.5)18    except Exception:19        checks["feature_store"] = False2021    ok = all(checks.values())22    return JSONResponse({"ready": ok, "checks": checks}, status_code=200 if ok else 503)

Here is the outage that comes from getting this wrong. Put a database check in the liveness probe. The database has a 30-second blip. Every replica's liveness probe fails simultaneously, so the orchestrator kills every replica at once. They all restart, all try to reconnect to a database that is still recovering, and now that database is being hammered by a thundering herd of reconnects. A 30-second blip becomes a fifteen-minute outage, caused entirely by the health check.

Liveness must only answer "is this process still capable of responding at all". Anything external belongs in readiness, where the response is to stop sending traffic — not to destroy the process.

The start_period setting is the other half of this. Loading a PyTorch model takes 15–30 seconds; without a grace period the probe fails during start-up and the container is killed before it ever becomes ready, producing a restart loop that looks like a crash.

Load testing before launch, not after

The reason to load test is not to produce a number for a slide. It is that queueing behaviour is non-linear and completely invisible at low traffic.

Take a service that takes 200 ms per request with 4 workers, so capacity is 4 / 0.2 = 20 requests per second. Utilisation is arrival rate divided by capacity. Standard queueing theory for four workers fed from one queue with random arrivals (the M/M/4 model) gives these expected response times:

Up to about 70% utilisation, the service barely notices the load. Then it bends: going from 18 to 19 requests per second — a 5.5% traffic increase — nearly doubles latency, and the next half request per second doubles it again. That cliff is why "we tested at half our expected load and it was fine" is not evidence of anything, and why capacity planning targets 60–70% utilisation rather than 95%. The headroom is not waste; it is the only thing standing between you and the cliff.

Locust

1from locust import HttpUser, task, between2import random, base64, pathlib34IMAGES = [base64.b64encode(p.read_bytes()).decode()5          for p in pathlib.Path("samples").glob("*.jpg")]67class InferenceUser(HttpUser):8    wait_time = between(0.5, 2.0)910    @task(9)11    def predict(self):12        with self.client.post("/predict",13                              json={"image_b64": random.choice(IMAGES)},14                              catch_response=True, name="/predict") as r:15            if r.status_code != 200:16                r.failure(f"status {r.status_code}")17            elif r.elapsed.total_seconds() > 1.0:18                r.failure("exceeded 1s budget")1920    @task(1)21    def health(self):22        self.client.get("/healthz", name="/healthz")

locust -f loadtest.py --host http://localhost:8000 \       --users 200 --spawn-rate 10 --run-time 10m --headless --csv results

Two details make this test meaningful rather than decorative. Use real sample inputs — a 3 KB synthetic payload exercises none of your JPEG decoding, so you measure a pipeline you do not run. And ramp gradually with --spawn-rate: dropping 200 users on instantly measures your cold-start path, not your steady state.

Why percentiles, and never the mean

Suppose 1,000 requests: 950 complete in 50 ms, and 50 take 2,000 ms because they miss a cache.

A dashboard showing "average latency 148 ms" against a 500 ms target looks healthy. But the p50 is 50 ms, the p95 is 50 ms, and the p99 is 2,000 ms. One request in twenty takes two seconds. If each user session makes 20 requests, then most sessions contain at least one two-second stall — the probability of avoiding it entirely is $0.95^{20} = 0.36$, so 64% of sessions hit it.

The mean hid a problem affecting nearly two-thirds of your users. Alert on p95 and p99; keep the mean off your dashboards entirely.

Alerting on symptoms, not causes

An alert should mean a human needs to act now. Everything else is a dashboard.

1groups:2- name: inference3  rules:4  - alert: HighErrorRate5    expr: |6      sum(rate(inference_requests_total{status="server_error"}[5m]))7        / sum(rate(inference_requests_total[5m])) > 0.058    for: 5m9    labels: {severity: page}10    annotations:11      summary: "Error rate {{ $value | humanizePercentage }} over 5m"1213  - alert: LatencyBudgetBreached14    expr: |15      histogram_quantile(0.99,16        sum(rate(inference_duration_seconds_bucket[5m])) by (le)) > 1.017    for: 10m18    labels: {severity: page}1920  - alert: ConfidenceCollapse21    expr: |22      sum(rate(prediction_confidence_bucket{le="0.5"}[1h]))23        / sum(rate(prediction_confidence_count[1h])) > 0.3024    for: 30m25    labels: {severity: ticket}26    annotations:27      summary: "Over 30% of predictions below 0.5 confidence - probable data drift"2829  - alert: NoTraffic30    expr: sum(rate(inference_requests_total[10m])) == 031    for: 10m32    labels: {severity: page}

The for: clause is what separates a usable pager from one people mute. It requires the condition to hold continuously for that duration, which filters transient spikes. Without it, a single slow garbage collection pages someone at 3am.

NoTraffic is the alert teams forget, and it catches the worst class of failure: everything looks green because nothing is happening. A misconfigured load balancer sending zero requests produces a 0% error rate and excellent latency.

Tie thresholds to an error budget rather than to a number that felt right. A 99.9% availability target over 30 days allows 43,200 × 0.001 = 43.2 minutes of downtime per month. Burning error budget fourteen times faster than sustainable for an hour consumes about 2% of the month's budget in that hour — that is worth a page. Burning it at 1.2× for an hour is not.

What to instrument before you ship

The three systems in this lesson answer three different questions and none substitutes for another. Metrics tell you that something is wrong, within seconds. Logs tell you which requests and why. Load tests tell you where the cliff is, before your users find it.

A workable minimum for a first deployment, in the order you should build it: a JSON formatter and a correlation-ID middleware, because retrofitting these after an incident does not help you with that incident. Then a counter and a latency histogram with buckets straddling your SLO. Then separate /healthz and /readyz with the dependency checks only in the second. Then a confidence histogram, which is the one ML-specific signal that gives you early warning of drift. Then a ten-minute Locust run at 1.5× your expected peak, using real inputs.

The test of whether you have done enough is concrete: pick a request that happened yesterday and try to reconstruct what it did — which replica, which model version, how long each stage took, and what it predicted. If you can do that in under two minutes, your observability is adequate. If you cannot, you will be writing "unable to reproduce" on support tickets, and eventually on incident reports.