fix(issue-14): record every event on disk before the wire publish

Round-2 review of 952657e (reviewer-grok-01): R1's disk-heartbeat
evidence comes from events.log, but publish_event appended to it only
after with_retry(_publish_once) returned - after the broker ACK or all of
its retries. With the public broker at ~5 s per publish, an agent's
heartbeat reached the disk after the grace window and the live job was
closed as deadline_timeout (test_wrapper_idle_timeout_grace_accepts_disk_heartbeat
failed 2/2 on 952657e here, as it did for the reviewer).

- publish_event: new record_local_event appends the prepared payload to
  events.log right after prepare_event (validation and seq allocation
  first) and before the wire publish; record_outcome takes
  local_event_recorded=True so the line is not written twice, while the
  audit "published" entry and the status sync stay after the publish
- DelegationService.publish_event: the same local-first order
- wrapper comment and VERSIONS.md v4.4.2 item 6 now say the heartbeat is
  on disk before the publish; new-test count 21
- tests: the heartbeat is already in events.log when the publish starts
  (and is recorded once), and a publish failing on every retry leaves one
  local record with published=False in the audit; both fail on 952657e.
  The wrapper disk-heartbeat test keeps the real publish_event path and
  now passes 3/3 at the same broker latency

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01HCGpJXhSZasJLU38ksDghe
This commit is contained in:
GodopuandClaude Opus 5 committed 2026-09-13 03:01:53 +09:00
1 parent 952657efb4
commit ebe58f6be0
5 files changed
+109 -13

No files matched your search

@@ -162,14 +162,31 @@ def prepare_event(job_id, event, detail="", data=None,
return PreparedEvent(job_id, event, detail, seq, topic, retain, payload, body, config)
def record_local_event(prepared: PreparedEvent, registry_dir: str) -> None:
"""Append the event to the job's on-disk events.log BEFORE any wire publish.
The delegate wrapper reads this log as liveness evidence once its
subscriber has idled out (`_recent_disk_heartbeat`). Recorded only after
the publish - which blocks on the broker ACK and its retries - a slow
broker's heartbeat reached the disk too late for that grace window, and
live jobs were closed as deadline_timeout. Best effort, like the rest of
the record.
"""
registry.append_event(prepared.job_id, registry_dir, prepared.payload)
def record_outcome(prepared: PreparedEvent, registry_dir: str,
publish_ok: bool, publish_error: Optional[str],
expected_dispatch_token: Optional[str] = None,
expected_attempt: Optional[int] = None) -> None:
expected_attempt: Optional[int] = None,
local_event_recorded: bool = False) -> None:
"""Persist the audit record, the registry event log and the status sync.
All three are best effort and all three happen whether or not the publish
succeeded — that is the contract G-1/G-2/G-4 pin down.
succeeded — that is the contract G-1/G-2/G-4 pin down. A caller that
already wrote the registry event log before publishing
(``record_local_event``) passes ``local_event_recorded=True`` so the line
is not appended twice.
"""
mqtt_common.append_event(prepared.job_id, {
"event": "published",
@@ -184,7 +201,8 @@ def record_outcome(prepared: PreparedEvent, registry_dir: str,
"publish_error": publish_error,
})
registry.append_event(prepared.job_id, registry_dir, prepared.payload)
if not local_event_recorded:
registry.append_event(prepared.job_id, registry_dir, prepared.payload)
new_status = EVENT_TO_STATUS.get(prepared.event)
if new_status:
try:
@@ -337,6 +355,10 @@ def main(argv=None) -> int:
logger.error("%s", exc)
return 1
# Local first: the event reaches events.log before the publish can block on
# the broker ACK and its retries (see record_local_event).
record_local_event(prepared, args.registry_dir)
# Policy Note: seq consumption on failure is intentional (see prepare_event)
# and the failure is documented explicitly in the audit record.
publish = with_retry(
@@ -362,7 +384,8 @@ def main(argv=None) -> int:
record_outcome(prepared, args.registry_dir, publish_ok, publish_error,
expected_dispatch_token=sync_expected_token,
expected_attempt=sync_expected_attempt)
expected_attempt=sync_expected_attempt,
local_event_recorded=True)
if not publish_ok:
return 2
@@ -84,6 +84,9 @@ class DelegationService(object):
data=data, registry_dir=self.registry_dir,
dispatch_token=eff_dispatch_token, attempt_id=eff_attempt_id,
)
# Local first, as in the CLI: the event reaches events.log before the
# publish can block on the broker (see publish_event.record_local_event).
publish_event.record_local_event(prepared, self.registry_dir)
publisher = self._publisher
if publisher is None:
from lib_py.delegation.publisher import OneShotPublisher
@@ -93,6 +96,7 @@ class DelegationService(object):
prepared, self.registry_dir, ok, error,
expected_dispatch_token=eff_dispatch_token,
expected_attempt=eff_attempt_id,
local_event_recorded=True,
)
return 0 if ok else 2
@@ -621,13 +621,13 @@ _within_deadline() {
}
# ISSUE-14: agent-agnostic liveness. publish_event appends every event to the
# job's on-disk events.log right after its wire publish attempt, whether that
# publish succeeded or not, so a `progress` heartbeat the subscriber never saw
# (it had already idled out, or the broker dropped it) is still visible here -
# late by at most its publish retries while the broker is failing. An agent
# running its tests in a background shell looks idle to herdr and shows no
# busy token, yet keeps heartbeating - this is the only evidence that covers
# that case.
# job's on-disk events.log BEFORE its wire publish (record_local_event), so a
# `progress` heartbeat the subscriber never saw (it had already idled out, or
# the broker dropped it) is visible here the moment it is sent - a slow or
# failing broker no longer delays it by its publish retries. An agent running
# its tests in a background shell looks idle to herdr and shows no busy
# token, yet keeps heartbeating - this is the only evidence that covers that
# case.
_recent_disk_heartbeat() {
local job_id="$1" window="$2" f="$REGISTRY_DIR/$job_id.events.log"
[ -f "$f" ] || return 1