Skip to content

fix(tracing): keep the end of a long session's trace, not the start - #397

Open
plombeer31 wants to merge 2 commits into
mainfrom
fix/trace-keeps-the-tail
Open

fix(tracing): keep the end of a long session's trace, not the start#397
plombeer31 wants to merge 2 commits into
mainfrom
fix/trace-keeps-the-tail

Conversation

@plombeer31

Copy link
Copy Markdown
Collaborator

The report

From Discord #feedback-and-bugs, thegreatteacher, 2026-09-09:

if I ask atomic agent to perform a self diagnostic for a session, the agent is not able to make proper assessments by checking traces due to trace truncations (I am not exactly sure). Proper self diagnosis was only possible via the SQLite session store. It just feels like trace logs are not that useful for some cases for the agent to perform self diagnosis to investigate "what went wrong".

The reporter said themselves they were not sure of the cause, and I have no reproduction of their exact session. What follows is the defect an audit of the trace sink turned up — it matches the symptom exactly, but treat it as "this is a real bug that produces that symptom", not as a confirmed reproduction of their case.

The mechanism

createNdjsonTraceSink (src/tracing/trace/trace-sink.ts) capped a session's NDJSON file at tracing.trace.maxBytesPerSession — 10 MB by default (src/config/config-schema.ts). On reaching the cap it appended one trace_truncated marker, set overflown, and then silently dropped every later event for that session. resolveState re-derived overflown from the existing file size, so the state survived restarts: once a session's trace hit the cap it was mute for good.

The cap was therefore enforced from the wrong end. A long session kept a pristine record of its opening minutes and lost everything after — and the end is where "what went wrong" lives. An agent asked to diagnose its own long session would read a trace that stops well before the failure, which is exactly the complaint.

The fix

The cap is now honoured by dropping the oldest events instead of refusing new ones.

  • When an append would cross the cap, the sink rewrites the file keeping its tail: whole leading NDJSON lines are dropped until the file is at half the cap, then appending resumes.
  • A trace_truncated marker is left at the seam carrying new optional droppedEvents / droppedBytes fields, so no reader mistakes the first surviving row for the start of the session. The counts are cumulative and are read back off the previous marker rather than from memory, so they stay right across restarts and across repeated trims. The marker takes the seq and ts of the last dropped event, so the file stays ordered by both.
  • A leading session_started row is preserved when the file has one, so trace list still shows the start time and trace replay still finds the working directory after a trim.
  • overflown is gone. A resumed session whose file is already over the cap — including one an older build left stranded at the cap — trims on its next event and keeps recording.

One file per session, unchanged. traceFilePath still resolves to <dir>/<sessionId>.ndjson and nothing rotates into sibling files. I checked all four readers — src/cli/trace-command.ts (show/replay/export), src/tui/debug-bundle/write-debug-zip.ts, src/tui/issue-report/write-report-zip.ts and eval-memory/harness/postmortem-trace.ts — and none needed a change: they read the whole file, skip unparsable lines, tolerate a missing session_started, and none depend on seq starting at 0 or being unique. redactTraceNdjson passes the new fields through, and trace_truncated is already in its errors-level allowlist. trace-formatter.ts now prints the two counts. The TraceEvent union gained only two optional fields, so no exhaustive switch moved.

Crash safety. The new content is written to a temp file in the same directory and renamed over the original, so the trace is never missing or half-written if the process dies mid-rewrite. A trim that cannot be completed logs once and degrades to the old behaviour (stop writing) rather than losing the file; nothing throws into the caller.

Cost

The trim is O(file size) and runs on the append path, so it is bounded two ways:

  • It leaves the file at half the cap, so one rewrite of at most cap bytes buys cap/2 bytes of appends — an amortised ≤2 bytes rewritten per byte traced, no matter how long the session runs. At the 10 MB default: a ~10 MB read plus a ~5 MB write plus a rename, once per 5 MB of trace.
  • A file already at or below the target is never rewritten. That is the case where the event itself is the thing that does not fit; that one event is dropped (with a single warning per session) and the file is left alone. Without this guard a stream of events larger than half the cap would pay a full rewrite each.

Worst case is therefore one cap-sized read + cap/2-sized write per cap/2 bytes of trace appended, synchronous on the emitting thread — the same thread that was already doing a synchronous appendFileSync per event.

Tests

Extended src/tracing/trace/trace-sink.test.ts (2 cap tests replaced by 9):

  • the cap trims instead of going mute, and the tail of a long run is present while the head is gone;
  • the file stays under the cap on every single append;
  • the marker states the loss, exactly one marker survives repeated trims, its count keeps growing, and dropped + still-on-disk == every event ever handed to the sink;
  • the trimmed file is parseable line-by-line and non-decreasing in seq;
  • session_started survives a trim, with the marker right behind it;
  • a resumed session whose file is already over the cap resumes writing;
  • a trim that cannot be written (read-only directory) does not throw, does not lose or mangle what was already recorded, and then goes quiet instead of retrying per event;
  • the no-cap-hit path is byte-identical to before (asserted against the exact expected bytes);
  • an event larger than the cap is dropped without a rewrite and the sink keeps working afterwards.
npm run lint                                    # tsc --noEmit, clean
npx vitest run src/tracing src/cli/trace-command.test.ts \
  src/cli/trace-formatter.test.ts src/tui/issue-report
#   Test Files  14 passed (14)
#   Tests      116 passed (116)
npx vitest run src/tui/debug-bundle             # 2 passed

Vacuity check: stashing only the three src changes (trace-sink.ts, trace-event.ts, trace-formatter.ts) and keeping the new test file gives 5 failed | 6 passed — the five that fail on origin/main are trims the head at the cap instead of going mute, states the loss in the marker and keeps it growing across trims, preserves session_started so trace list/replay still find the header, resumes writing into a file that is already over the cap, and drops a single event larger than the cap without rewriting. The four that pass on both are deliberate: two are the pre-existing suite, one is the byte-identical no-regression guard, and two are property guards (file stays under the cap, file stays parseable and ordered) that the old code also satisfied by never writing at all.

Also updated AGENTS.md §"Traceability and replay", which documented trace_truncated as a final marker after which events are dropped.

The per-session NDJSON cap was enforced from the wrong end. On reaching
`tracing.trace.maxBytesPerSession` (10 MB by default) the sink appended
one `trace_truncated` marker, set `overflown`, and dropped every later
event for that session — permanently, and across restarts, because
`resolveState` re-derived `overflown` from the file size. A long session
therefore kept a pristine record of its opening minutes and nothing at
all about its end, which is where "what went wrong" lives.

The cap is now honoured by dropping the OLDEST events instead of
refusing new ones. When an append would cross it the sink rewrites the
file keeping its tail: whole leading lines go until the file is at half
the cap, a `trace_truncated` marker is left at the seam carrying
`droppedEvents` / `droppedBytes`, and writing continues. A leading
`session_started` row is preserved so `trace list` and `trace replay`
still find the header. There is still exactly one file per session, so
`trace show/export`, the debug bundle, the issue report and the eval
harness need no changes.

The rewrite goes through a temp file in the same directory and an
atomic rename, so the trace is never missing or half-written; a trim
that cannot be completed degrades to the old stop-writing behaviour and
never throws into the caller. Halving on each trim bounds the cost to
an amortised two bytes rewritten per byte traced, and a file already at
the target is never rewritten — a single event bigger than the cap is
dropped on its own instead of triggering a rewrite per event.
Review follow-ups on the head-trimming sink.

The cost bound the trim relies on was not enforced. `bytesWritten <=
target` skips a rewrite only when the file can reach the target, and a
trim cannot always get there: a preserved `session_started` plus the
marker is irreducible. When that floor sits above the target the guard
never fires and every single event pays a whole-file read + write +
rename. Measured on a 1.4 KB header at a 2 KB cap: 54 rewrites over 59
events; at a 256-byte cap, 40 over 40. Two changes fix it — the header
is only preserved while it is at most half the target (it exists to
introduce a tail, not to crowd it out), and the size a trim actually
produced is remembered so a file already at its floor is left alone.
Same measurements after: 8 over 59, and 2 over 40 — with more of the
session on disk, not less.

Also:

- flush the temp file before renaming it. `rename` is atomic for the
  directory entry, not for the data behind it, so a power cut after the
  rename could leave the trace pointing at an unwritten extent — losing
  the whole file rather than half of it.
- sweep temp files a crashed trim stranded. A process killed between
  the write and the rename leaks up to half a cap of unredacted trace
  content under a name no reader lists, one per crash, forever. Only
  temps whose owning pid is gone are removed.
- count a file's unterminated last line as a dropped event, so
  `droppedEvents` still adds up on a trace another process left
  mid-append.

Tests. Every cap test ran at 600 bytes, where the target (300) is below
`MARKER_BUDGET_BYTES` — the trim degenerates to "wipe everything but the
header" and no surviving tail is ever cut, so the newline rounding was
never executed. Cutting mid-line passed the whole suite. Added coverage
at caps where a real tail survives (asserting each surviving row is
byte-identical to the event that was emitted), for the rewrite bounds
above, for the temp sweep, and for the marker's seq and the
unterminated-line count.

The `trace_truncated` marker no longer means "the trace stops here", so
the eval postmortem's rendered line and two stale comments that still
described the old cap behaviour are corrected.
plombeer31 added a commit that referenced this pull request Sep 10, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant