What to log for a prompt A/B test post-mortem

Most teams run prompt A/B tests and then realize they logged only the aggregate win rate. Solid logging for prompt A/B test analysis means recording the exact inputs, model routing, token counts, and evaluation outcomes per request, so a post-mortem can isolate failure modes instead of guessing.

Step 1: Define a flat, typed log schema

Before writing any instrumentation, decide the fields you will emit on every LLM call in the experiment. A nested JSON blob is unqueryable; flatten into explicit keys.

{
  "ts": "2024-05-12T18:22:01.123Z",
  "experiment_id": "checkout_summary_v3",
  "variant": "A",
  "request_id": "req_8f2c",
  "user_id": "usr_123",
  "model_requested": "gpt-4o-mini",
  "model_served": "gpt-4o-mini",
  "prompt_version": "sys_2.1_user_1.4",
  "temperature": 0.2,
  "finish_reason": "stop",
  "prompt_tokens": 412,
  "completion_tokens": 88,
  "latency_ms": 740,
  "cache_read_tokens": 0,
  "fallback_triggered": false,
  "error": null
}

Keep the schema stable across variants. If you add a field mid-experiment, backfill or accept a null column—otherwise your post-mortem joins break.

Step 2: Instrument the request path at the client

Wrap your LLM client so every call logs the schema above. Do not log inside business logic; intercept at the boundary.

import time
import structlog

log = structlog.get_logger()

def tracked_complete(client, experiment_id, variant, user_id, **kwargs):
    start = time.monotonic()
    resp = client.chat.completions.create(**kwargs)
    elapsed = int((time.monotonic() - start) * 1000)
    choice = resp.choices[0]
    log.info(
        "prompt_ab_call",
        experiment_id=experiment_id,
        variant=variant,
        request_id=resp.id,
        user_id=user_id,
        model_requested=kwargs.get("model"),
        model_served=resp.model,
        prompt_version=kwargs.get("prompt_version", "unknown"),
        temperature=kwargs.get("temperature", 1.0),
        finish_reason=choice.finish_reason,
        prompt_tokens=resp.usage.prompt_tokens,
        completion_tokens=resp.usage.completion_tokens,
        latency_ms=elapsed,
        fallback_triggered=False,
        error=None,
    )
    return resp

The wrapper captures the actual served model and finish reason—two fields that expose silent regressions when a provider substitutes a different model.

Step 3: Capture routing, fallback, and cache signals

A post-mortem must distinguish “variant A is worse” from “variant A hit a degraded provider and timed out.” If you route through n4n.ai, the gateway provides per-token usage metering and automatic fallback; log the model actually returned and the usage object, since a fallback changes which model variant you are really comparing.

Extend the logger to record routing metadata:

def log_routing(resp, fallback=False, cache_read=0):
    log.info(
        "prompt_ab_routing",
        request_id=resp.id,
        model_served=resp.model,
        fallback_triggered=fallback,
        cache_read_tokens=cache_read,
    )

Cache hits matter: a variant that looks cheaper may just be benefiting from a warm prompt cache. Forwarded cache-control hints from the gateway let you attribute that correctly.

Step 4: Attach evaluation and feedback asynchronously

Don’t block the request on grading. Emit a separate evaluation event keyed by request_id. This keeps logging for prompt A/B test analysis decoupled from latency-critical paths.

def log_evaluation(request_id, score, grader="human"):
    log.info(
        "prompt_ab_eval",
        request_id=request_id,
        score=score,           # 1-5 or binary
        grader=grader,
        ts=time.time()
    )

If you run an automated judge, label it explicitly. Mixed grader sources without a grader field will corrupt your post-mortem aggregates.

Step 5: Ship to a columnar store, not just stdout

Structlog to stdout is fine for dev, but for analysis you need a warehouse. Pipe logs to BigQuery, ClickHouse, or DuckDB via a sidecar.

# example: tail json logs to a file and load with duckdb
python app.py 2> >(jq -c '. | select(.event=="prompt_ab_call")' > calls.jsonl)
python -c "import duckdb; duckdb.connect('exp.db').execute('CREATE TABLE calls AS SELECT * FROM read_json_auto(\"calls.jsonl\")')"

Separate tables for calls, routing, and eval joined on request_id give you clean SQL without wide-row drift.

Step 6: Run the post-mortem query

With the tables loaded, the real work starts. Example: compare variants on error rate, latency p95, and mean human score.

SELECT
  c.variant,
  count(*) AS n,
  avg(CASE WHEN c.finish_reason != 'stop' THEN 1 ELSE 0 END) AS non_stop_rate,
  quantile_cont(c.latency_ms, 0.95) AS p95_latency,
  avg(e.score) AS mean_score
FROM calls c
LEFT JOIN eval e ON c.request_id = e.request_id
WHERE c.experiment_id = 'checkout_summary_v3'
GROUP BY c.variant;

If variant B has a higher score but also a 12% non_stop_rate due to fallback, your post-mortem just prevented a bad ship. Drill into routing to see which provider failed.

Step 7: Verify the pipeline before you trust it

A post-mortem is only as good as the logs. Verify success by replaying one request per variant and asserting the full chain landed.

1. Send a canary call with experiment_id='verify'.
2. Confirm a prompt_ab_call row exists with correct variant and model_served.
3. Confirm a joined eval row appears after grading.
4. Check that fallback_triggered is false under normal conditions and flips true when you force a provider outage.

If any of these fail, fix instrumentation before running the real test. Logging for prompt A/B test analysis is worthless if the request_id join is silently dropping 30% of rows.

Run this check in CI against a sandbox key. The cost is trivial; the alternative is a post-mortem built on ghosts.