fix(automation): tighten mark→tail log correlation (doMark seq race + tail eviction-gap signal) (#3756)#3793
Conversation
Two accuracy edges in the agent automation bridge's log-correlation helpers, both in src/core/AutomationServer.cpp. Neither touches the radio, TX safety, or the captured log data — only the precision of the mark→tail bracketing pattern. 1. doMark seq/mono_us race. doMark injected the marker via qCInfo() (which runs the log tap synchronously and assigns the marker its seq), then re-read m_logSeq / m_logRing.back() after re-acquiring m_logMutex. A concurrent logging thread pushing in that gap could bump m_logSeq and append a newer event, so the seq/mono_us handed back could belong to a *later* event — and `log tail since=<seq>` would then skip whatever was logged right after the mark, defeating the bracket. Fix: capture the marker's own seq/mono *inside* the tap via a thread_local sink (g_markSink). The tap runs synchronously on doMark's thread, so only that thread's own tap call populates the sink; loggers on other threads see a null sink and leave it alone. Falls back to the resident tail only if the tap never fired (lcAutomation info disabled). 2. tail since=<seq> under-reported silently after ring eviction. The ring caps at kLogRingMax = 8000; a tail whose `since` had already been evicted returned only the resident suffix with no signal earlier matching events were dropped. Fix: include the oldest retained seq (`oldest`) in the tail response so a driver detects a gap whenever `since < oldest`. Additive field, no behavior change for existing callers. tools/automation_logwatch.py: expose the new field via tail_window() + gap_after() (tail() unchanged for compatibility) and document oldest. Proven with the agent automation bridge on the fixed build: - bracket integrity: mark, emit 25 post-mark lines, tail(since=mark_seq) captured all 25; the event at seq==mark_seq is the MARK line itself. - real eviction: held since=10642, generated 8600 marks, oldest rose to 12791 > 10642 → gap_after=True (was silently undetectable before). Fixes aethersdr#3756. Refs aethersdr#3738, aethersdr#3646. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
There was a problem hiding this comment.
Reviewed both changes against the surrounding code in AutomationServer.cpp. This is a clean, well-reasoned fast-follow — the analysis in the PR body holds up.
Bug 1 — thread_local sink: correct and robust. MarkCapture/g_markSink live in the existing anonymous namespace (internal linkage, no ODR concern). The key safety property is solid: because g_markSink is thread_local and points at a stack local on doMark's thread, only that thread's own synchronous tap call ever writes to cap; other threads' taps read their own (null) sink. And it degrades safely even if the synchronous-same-thread assumption were ever violated — g_markSink is reset to nullptr before the tap could fire late, so cap.set stays false and you take the resident-tail fallback rather than dereferencing a dangling pointer. Nice. The !cap.set fallback for the lcAutomation-disabled case is the right call too.
Bug 2 — oldest field: good, with one boundary nit. Computing oldest from m_logRing.front().seq under the same lock is correct. One off-by-one in the gap predicate, though:
tail returns events with e.seq > since (strict — the mark line at seq == since is excluded). gap_after flags a gap when since < oldest. Consider oldest == since + 1: the mark line itself was evicted, but the first wanted event (since + 1) is still resident as the ring front — so the post-mark bracket is actually complete, yet gap_after returns True. The strictly-correct condition is oldest > since + 1 (i.e. the first event after the mark was evicted). It only ever over-reports, never misses a real gap, so it errs in the safe direction — but since this is a precision tool, you may want to tighten it to avoid spurious "truncated window" signals at that exact boundary.
Minor: the oldest signal detects ring eviction but not n-truncation. A driver bracketing with the default tail (n=100) where >100 events match since silently gets only the newest 100, with no eviction and so gap_after returns False despite a truncated window. Worth a one-line note in the tail_window docstring that callers bracketing a region should pass a generous n (the oldest gap check assumes the window wasn't n-capped).
Neither blocks merge. Python wrapper keeps tail() compatible and documents the new path well. Thanks for the careful write-up and the reproduction evidence, @jensenpat.
🤖 aethersdr-agent · cost: $4.0001 · model: claude-opus-4-8
ten9876
left a comment
There was a problem hiding this comment.
Reviewed the mark/tail precision fixes — both correct.
Bug 1 (doMark seq race): the thread_local g_markSink captures the marker's seq/mono inside the synchronous MARK tap, so it's the exact in-lock-assigned seq rather than a later event's read after a re-lock gap. thread_local ⇒ only doMark's own thread publishes; concurrent loggers see null and skip — no race. Clean fallback when lcAutomation info logging is off.
Bug 2 (tail eviction gap): the additive 'oldest' field (front-of-ring seq, under the same lock) lets a driver detect truncation via since < oldest. Backward-compatible; logwatch.py exposes tail_window()/gap_after() with tail() unchanged.
Verified the patch anchors (the tap lambda + doLog tail return) survive #3819 untouched, so the 3-way merge is clean despite the line shift.
Non-blocking nit: g_markSink arm/disarm isn't RAII-guarded — theoretical dangle if qCInfo threw, which it doesn't. A small RAII guard would make it bulletproof.
Automation-only, no TX/radio impact, live mark/tail proof included. Thanks @jensenpat.
Summary
Fast-follow to #3738 fixing two accuracy edges in the agent automation bridge's log-correlation helpers (
mark/tail). Both live insrc/core/AutomationServer.cppand only affect the precision of themark → tailbracketing pattern — neither touches the radio, TX safety, or the captured log data. Severity: low.Bug 1 —
doMarkcould return aseq/mono_usbelonging to a later event (race)doMarkinjected the marker viaqCInfo()— which runs the log tap synchronously and assigns the marker its sequence — then re-readm_logSeq/m_logRing.back()on the next line after re-acquiringm_logMutex. A concurrent logging thread pushing in that unlocked gap bumpsm_logSeqand appends a newer event, so both the returnedseqandmono_uscould belong to an event logged after the mark.log tail since=<seq>would then skip whatever was logged immediately after the mark — exactly what the bracket is meant to capture.Fix: capture the marker's own seq/mono inside the tap via a
thread_localsink (g_markSink). BecauseqCInfo()runs the tap synchronously ondoMark's thread, only that thread's own tap call populates the sink; loggers on other threads see a null sink and leave it untouched (no member-flag race). Falls back to the resident tail only if the tap never fired (i.e.lcAutomationinfo logging disabled).Bug 2 —
tail since=<seq>under-reported silently after ring evictionThe ring caps at
kLogRingMax = 8000. Atail since=<old_seq>whose seq had already been evicted returned only the resident suffix with no signal that earlier matching events were dropped — a driver could mistake a truncated window for a complete one.Fix: include the oldest retained seq (
oldest) in thetailresponse, computed under the same lock. A driver detects a gap wheneversince < oldest. Additive field, no behavior change for existing callers.tools/automation_logwatch.pyexposes it viatail_window()+gap_after()(tail()unchanged for compatibility) and documents it.How the agent automation bridge proved it
Built
RelWithDebInfo, launched withAETHER_AUTOMATION=1(RX-only, no radio, zero TX), and drove themark/tailpath throughtools/:Bug 1 — bracket integrity
Bug 2 — real eviction signal
Before this PR the
tailresponse had only{ok, events, seq}—oldestwas absent, so the gap was undetectable.Fixes #3756. Refs #3738, #3646.
💻 Generated with Claude Code (Opus 4.8) with architecture by @jensenpat