Repository navigation
Trip logging v2: four timestamps per trip (sent / received / duration / returned) for per-leg attribution #5702
Description
Trip logging v2 — four timestamps per trip (design; Drew's request 2026-11-04)
Trip logging v1 (landed 2026-11-04 on #5343) records, per laptop-agent call: client-side {ts, trip, path, total_ms, status} on the sandbox and daemon-side {ts, trip, kind, cmd0, cmd_sha256, duration_ms, exit, out_bytes, err_bytes} on the laptop. That splits a trip into "daemon time" vs "everything else" — but "everything else" mixes the outbound leg, the return leg, and proxy time, which is exactly the split needed when the fleet proxy is the suspect (as in the 2026-11-04 incident, where the working data was: warm total ~0.39–0.45 s, daemon duration ~1 ms).
Schema v2 — one line per event, four timestamps
Client line (sandbox ~/.local/state/laptop-agent/trips.jsonl), extended:
{"v": 2, "ts": "<t0 sent>", "trip": "<12-hex>", "path": "/exec",
"t_sent": 1730000000000, "t_returned": 1730000000445,
"total_ms": 445, "status": 200}Daemon line (laptop ~/.local/state/laptop-agent/trips.jsonl), extended:
{"v": 2, "ts": "<t1 received>", "trip": "<12-hex>", "kind": "exec",
"t_received": 1730000000102, "duration_ms": 3,
"cmd0": "echo", "cmd_sha256": "…", "exit": 0, "out_bytes": 5, "err_bytes": 0}Joining on trip yields the full attribution:
- outbound leg =
t_received − t_sent(sandbox proxy + runtime CONNECT proxy + tailnet) - daemon work =
duration_ms - return leg =
t_returned − (t_received + duration_ms) - total =
t_returned − t_sent(= existingtotal_ms, kept for continuity)
Constraints (unchanged from v1, hard requirements)
- Exactly one O_APPEND write per event on each side; logging failure is swallowed and never affects the request path; no measurable perf cost (v1 evidence: none).
- No raw command text beyond
cmd0(first token) +cmd_sha256; no env, headers, or tokens — unchanged. - Response wire shape unchanged: the daemon echoes
t_received(epoch ms) in the response body under an internal field the client strips before returning results to callers (v1 already strips internal byte-count fields the same way).
Clock skew
Cross-machine subtraction is only meaningful if both clocks agree. Both machines are expected to be NTP-disciplined (sandbox VM clock is platform-set; laptop is systemd-timesyncd), but this must be verified, not assumed: acceptance includes a skew probe — one trip where the client also records a daemon-echoed timestamp round-trip, bounding skew; if skew > ~50 ms, the leg split is published as approximate in the ingest. Millisecond epochs (not ISO strings) are carried in the new fields to keep arithmetic exact; ts stays for human readability.
Scope
- Client (
~/tools/laptop-agent.py): mint + recordt_sent/t_returned; the trip already travels via body field (the reliable carrier — the session proxy forwards bodies verbatim), header, and broker field; the daemon'st_receivedecho returns in the body. - Daemon (laptop
laptop_agent.py): stampt_receivedat request entry, echo it, include it in its log line. - Broker (
fleet proxy serve/ Python fallback): no change — it already forwards the trip untouched. - Follow-on (separate, already noted on design: laptop-agent — resident execution agent on the laptop (replace per-command SSH spawns) #5343): ingest of both sides' trip logs via the fleet-feed collector → Supabase, joining on
trip. Not part of this ticket. - When the
fleet laptop-agentdomain lands in the binary (currently a 0.1.0 stub), the v2 schema is the one it implements; the schema is versioned ("v": 2) so v1 lines remain parseable.
Acceptance
- A/B evidence on the laptop: one warm
/exectrip whose four timestamps reproduce total ≈ outbound + duration + return (±10 ms). - Skew probe result recorded on this issue.
- Trip logs on both sides show
v: 2lines; v1 readers (counts, status tallies) still work.
Acceptance criteria
- Each trip records four timestamps: sent, received, duration, and returned.
- Per-leg latency can be queried/reported from the recorded fields.
- Existing v1 trip logs remain readable (no destructive migration).
Activity
dezren39 commentedon Nov 5, 2026
Intake review
Related: fleet trip-logging observability; complements the quota/trip batch filed 2026-11-04 23:12–23:18Z. Notes: four timestamps (sent / received / duration / returned) are the minimum to attribute latency per leg instead of end-to-end only. Risk: schema change without v1 readability would blind existing reports. Suggested approach: add the fields additively, keep v1 readable, and add one per-leg latency report as the proof.
Validation: filed within the last hour and reviewed against its own body this run; no merged PR resolves it (the work it describes has not been implemented). Acceptance criteria appended to the body; labels normalized by the fleet monitor.
🤖 Agent note · intake enrichment
dezren39 commentedon Nov 5, 2026
🤖 Agent note · done
Triage — task 10136, issue #5702
Verified live (2026-11-05T13:49Z): the sandbox client trip log (
~/.local/state/laptop-agent/trips.jsonl) still emits v1 lines only — latest entries carry{ts, trip, path, total_ms, status}with nov/t_sent/t_returnedfields (grep for"v": 2in the log: 0 hits), and~/tools/laptop-agent.pycontains not_sent/t_receivedhandling. So v2 is unimplemented, not partially landed.Scope as filed is implementable as-is: client stamps + records
t_sent/t_returned, daemon stamps/echoest_received, broker unchanged, plus the clock-skew probe in acceptance. Constraints (single O_APPEND write, no raw command text beyondcmd0+hash, v1 lines stay parseable) are explicit. Route as an implementation (small_fix-class) task against the fleet laptop-agent code when prioritised; nothing blocks it except ordering against other #5343 follow-ons.Outcome for task 10136: triaged (not yet implemented, scope confirmed).
dezren39 commentedon Nov 8, 2026
Partial verification — staying open (2026-11-07 done-task-only audit, tracking: #7016).
Queue task(s) [10136] were marked done, and some work did land:
No merged change closes this issue's full scope, so the done status is not treated as completion. Remainder re-queued as triage task 11743.
dezren39 commentedon Nov 8, 2026
🤖 Agent note · handed off