Log time-to-first-byte, and script the Kibana dashboard

[krokicki]

Why

The access log measured only total request duration. For a proxy that streams multi-GB objects that number is dominated by transfer time, so a client pulling 27 GB over a slow link looked exactly like a stalled backend. Investigating a latency spike in production meant inferring the difference from the shape of the data rather than reading it.

Response headers only go out once the upstream store has answered, so the time to http.response.start separates what x2s3 and its backend cost from the body moving at whatever rate the client can take it.

What

TTFB in the access log. AccessLogMiddleware already intercepts http.response.start, so recording this costs one timestamp:

• JSON mode: labels.ttfb_ms. ECS has no time-to-first-byte field, so it goes under labels alongside the other custom dimensions.
• Text mode: ttfb=12.34ms appended to the access line.
• Two tests: TTFB is present and never exceeds event.duration, and the text line includes it.

scripts/kibana_dashboard.py builds the production overview dashboard from that measurement set — traffic and error rate, latency percentiles, throughput, per-node balance, per-target and per-client tables, user agents ranked by unique client IPs, and the failing-request stream. probe reports what the shipper actually indexed before anything is built; push is idempotent; dump prints the saved objects without touching Kibana.

Two things worth knowing if you ever touch this script:

• It creates saved objects with _bulk_create, not _import. _import replays Kibana's pre-8 Lens migrations against hand-written state and fails with a bare HTTP 500 and no message.
• Credentials come from var/kibana.env, not a repo-root .env — pydantic-settings loads that one into Settings, which forbids unknown keys, so an unrelated variable there stops the app and every test from starting.

Testing

53 passed in the pixi test environment (tests/test_log.py, test_file.py, test_base.py, test_xss_prevention.py). The AWS-backed tests were not run — they need outbound access to real S3, which this environment does not have.

🤖 Generated with Claude Code

[claude]

event.duration_ms is not a field anything writes. _log_request emits "event.duration": int(duration_s * 1_000_000_000) — ECS nanoseconds — and docs/StructuredLogging.md documents it under that name too. event.duration_ms appears exactly once in the repo: this line. There is no ingest pipeline or Filebeat processor in the tree that could derive it (the documented shipper config is pass-through json.keys_under_root: true), and F is a plain module-level dict with no env override, so this default is what actually runs.

Everything backed by F["duration"] therefore aggregates an unmapped field and renders empty rather than erroring:

• the probe p95 aggregation at L174-L176
• the percentile() Lens column at L210-L212, which feeds the p95 metric tile, the three-line "Latency percentiles" panel, and the p95 column of the "Targets: traffic and latency" table

Not leaving a committable suggestion because the fix needs a second edit: pointing at event.duration gives nanosecond magnitudes, and the formatter at L213-L214 hard-codes "suffix": " ms", so a 12 ms request would display as 12,000,000.0 ms. Either switch that format to Kibana's duration formatter ({"id": "duration", "params": {"inputFormat": "nanoseconds", "outputFormat": "asMilliseconds"}}) or convert ns→ms; the latency ms: print in probe needs the same treatment.

[claude]

Same class of mismatch as duration above: nothing logs a referrer. The header→field loop in _log_request is exactly two entries — user-agent and host — and a repo-wide search for refer(r)er hits only this file. docs/StructuredLogging.md's field table has no referrer row, and docker/nginx.conf sets no log_format/access_log, so nothing else in the tree supplies it either.

That makes the client-type split deterministic rather than descriptive. referred at L237-L239 is http.request.referrer: *, which compiles to an exists query and matches zero docs on an unmapped field, so "Browser, referred" is permanently 0 and every browser request lands in "Browser, no referrer" — a positive false claim on the panel that exists to identify embedded/web-app traffic. The buckets stay mutually exclusive and still sum to total traffic, so the blast radius is that one dead series plus the mislabeled one.

The cheap fix is to make the field real by extending the header loop in log.py:

for header, field in ((b"user-agent", "user_agent.original"), (b"host", "url.domain"), (b"referer", "http.request.referrer")):

(note the single-r wire spelling of the header vs. the double-r ECS field name). Otherwise, drop the referred split and collapse the two browser classes into one.