Skip to content

fix(automation): tighten mark→tail log correlation (doMark seq race + tail eviction-gap signal) (#3756)#3793

Merged
ten9876 merged 1 commit into
aethersdr:mainfrom
jensenpat:fix/3756-mark-tail
Jun 26, 2026
Merged

fix(automation): tighten mark→tail log correlation (doMark seq race + tail eviction-gap signal) (#3756)#3793
ten9876 merged 1 commit into
aethersdr:mainfrom
jensenpat:fix/3756-mark-tail

Conversation

@jensenpat

Copy link
Copy Markdown
Collaborator

Summary

Fast-follow to #3738 fixing two accuracy edges in the agent automation bridge's log-correlation helpers (mark / tail). Both live in src/core/AutomationServer.cpp and only affect the precision of the mark → tail bracketing pattern — neither touches the radio, TX safety, or the captured log data. Severity: low.

Bug 1 — doMark could return a seq/mono_us belonging to a later event (race)

doMark injected the marker via qCInfo() — which runs the log tap synchronously and assigns the marker its sequence — then re-read m_logSeq / m_logRing.back() on the next line after re-acquiring m_logMutex. A concurrent logging thread pushing in that unlocked gap bumps m_logSeq and appends a newer event, so both the returned seq and mono_us could 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_local sink (g_markSink). Because qCInfo() runs the tap synchronously on doMark'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. lcAutomation info logging disabled).

Bug 2 — tail since=<seq> under-reported silently after ring eviction

The ring caps at kLogRingMax = 8000. A tail 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 the tail response, computed under the same lock. A driver detects a gap whenever since < oldest. Additive field, no behavior change for existing callers. tools/automation_logwatch.py exposes it via tail_window() + gap_after() (tail() unchanged for compatibility) and documents it.

How the agent automation bridge proved it

Built RelWithDebInfo, launched with AETHER_AUTOMATION=1 (RX-only, no radio, zero TX), and drove the mark/tail path through tools/:

Bug 1 — bracket integrity

mark('FB3756-A') -> seq 10616
emit 25 post-mark log lines
tail(since=10616) captured 25 / 25  -> PASS
  first captured seq 10617 > mark seq 10616
  event at seq==mark_seq is the MARK line itself ('MARK FB3756-BRACKET')

Bug 2 — real eviction signal

hold since0 = 10642
generate 8600 marks (overflow the 8000-deep ring)
tail() -> seq 20790, oldest 12791
since0(10642) < oldest(12791)  -> gap_after = True
  driver can now DETECT the eviction; before this fix it was silent

Before this PR the tail response had only {ok, events, seq}oldest was absent, so the gap was undetectable.

Fixes #3756. Refs #3738, #3646.

💻 Generated with Claude Code (Opus 4.8) with architecture by @jensenpat

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>
@jensenpat jensenpat marked this pull request as ready for review June 24, 2026 14:55
@jensenpat jensenpat requested a review from a team as a code owner June 24, 2026 14:55

@aethersdr-agent aethersdr-agent Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 ten9876 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

@ten9876 ten9876 merged commit 4d02359 into aethersdr:main Jun 26, 2026
6 checks passed
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.

Automation log observability: tighten mark→tail correlation (doMark seq race + tail-since eviction-gap signal)

2 participants