From 5092981da730bc816db6c83b5d9ace65397d1cbc Mon Sep 17 00:00:00 2001 From: fujibee Date: Tue, 18 Aug 2026 17:38:53 -0700 Subject: [PATCH] fix(remote): say how many cycles have failed since the last success An engine that failed every cycle for six days kept the last success it ever had, and status printed it with nothing beside it -- so a machine that had not synced since the 13th reported 'last successful sync 2026-08-13' and read as working. The person who found it found it because two rosters disagreed. A success timestamp cannot say whether it is the present state, so the engine now records the failures too, counted since the last success. Refusals count: they do not advance the backoff counter, deliberately, but six days of nothing but refusals is six days of nothing synced. 'No cycle recorded' likewise splits: a young engine and one that has never completed a cycle said the same thing, and only the second is a fault. --- scripts/internal/remote-sync.mjs | 46 ++++++++++++++++++ scripts/remote.sh | 26 +++++++++- tests/remote_sync_engine.test.mjs | 67 ++++++++++++++++++++++++++ tests/test_remote_status_liveness.bats | 63 ++++++++++++++++++++++++ 4 files changed, 200 insertions(+), 2 deletions(-) diff --git a/scripts/internal/remote-sync.mjs b/scripts/internal/remote-sync.mjs index 893650b5e..138e58a2e 100755 --- a/scripts/internal/remote-sync.mjs +++ b/scripts/internal/remote-sync.mjs @@ -137,12 +137,42 @@ async function recordCycleSuccess(team, at, writeFileCall = writeFile) { const existing = JSON.parse(await readFile(path, "utf8")); if (typeof existing?.first_success_at === "string") first = existing.first_success_at; } catch { /* no stamp yet, or unreadable: this cycle is the first we can name */ } + // The failure fields are DROPPED, not carried: they count what has gone + // wrong since the last success, and this is that success. await writeFileCall(path, `${JSON.stringify({ type: "sync_cycle_stamp", first_success_at: first, last_success_at: at, })}\n`); } catch { /* best-effort: never fail a working cycle over its own bookkeeping */ } } +// The other half of the same record, and the reason it exists (#829). +// +// A success timestamp alone cannot say whether it is the present state. An +// engine whose every cycle has failed for six days keeps the last success it +// ever had, and `status` printed it with nothing beside it -- so a machine that +// had not synced since the 13th said "last successful sync 2026-08-13" and read +// as working. The person who found it found it by noticing two rosters +// disagreed, not from anything this client told them. +// +// Counted, not just stamped: "17 cycles have failed since" and "one failed a +// moment ago" are different situations, and the count is the part that says +// which. Same file, same lifetime, same best-effort promise as the success -- +// bookkeeping must never take down syncing, and under-reporting is the safe +// direction if this write is the thing that fails. +async function recordCycleFailure(team, at, consecutive, writeFileCall = writeFile) { + try { + const path = cycleStampPath(team); + let stamp = { type: "sync_cycle_stamp" }; + try { + const existing = JSON.parse(await readFile(path, "utf8")); + if (existing && typeof existing === "object") stamp = { ...existing, type: "sync_cycle_stamp" }; + } catch { /* no stamp yet, or unreadable: record the failure on its own */ } + await writeFileCall(path, `${JSON.stringify({ + ...stamp, last_failure_at: at, failures_since_success: consecutive, + })}\n`); + } catch { /* best-effort, exactly like the success above */ } +} + // A refusal the caller can act on, recorded where something can read it (#773). // // A remote may answer a write with a status meaning "the caller must do @@ -3090,6 +3120,7 @@ export async function runLoop(config, options, dependencies = {}) { const eventCall = dependencies.eventCall ?? event; const isRetryableCall = dependencies.isRetryableCall ?? isRetryable; const recordCycleCall = dependencies.recordCycleCall ?? recordCycleSuccess; + const recordCycleFailureCall = dependencies.recordCycleFailureCall ?? recordCycleFailure; const clearRefusalCall = dependencies.clearRefusalCall ?? clearRefusal; const recordRefusalCall = dependencies.recordRefusalCall ?? recordRefusal; const isRefusalCall = dependencies.isRefusalCall ?? isRefusal; @@ -3106,12 +3137,19 @@ export async function runLoop(config, options, dependencies = {}) { let catchUp = false; // start steady; the first cycle reveals any backlog let consecutiveFailures = 0; + // COUNTED SEPARATELY FROM `consecutiveFailures`, which drives the backoff and + // deliberately does not advance on a refusal. This one answers a different + // question -- "has anything worked since the last success" -- and a refusal + // is exactly as much of a no as a timeout is. Conflating them would leave the + // six-day refusal loop in #829 reporting a clean record. + let cyclesSinceSuccess = 0; for (;;) { const pushLimit = ceiling ?? (catchUp ? LARGE_LIMIT : STEADY_PUSH_LIMIT); const pullLimit = ceiling ?? LARGE_LIMIT; try { const result = await cycleCall(config, { pushLimit, pullLimit }, dependencies); consecutiveFailures = 0; + cyclesSinceSuccess = 0; // Here, and nowhere earlier: this is the one point at which a cycle is // known to have finished rather than to have been attempted. // @@ -3169,12 +3207,20 @@ export async function runLoop(config, options, dependencies = {}) { status: error?.status ?? null, code: error?.code ?? null, }); } catch { /* logging is best-effort */ } + cyclesSinceSuccess += 1; + try { + await recordCycleFailureCall(config.local_team, nowCall(), cyclesSinceSuccess); + } catch { /* best-effort, like every other note taken on this path */ } await sleepCall(MAX_BACKOFF_MS); continue; } if (!isRetryableCall(error)) throw error; consecutiveFailures += 1; + cyclesSinceSuccess += 1; + try { + await recordCycleFailureCall(config.local_team, nowCall(), cyclesSinceSuccess); + } catch { /* best-effort */ } const backoffMs = Math.min(MAX_BACKOFF_MS, BASE_BACKOFF_MS * 2 ** (consecutiveFailures - 1)); await sleepCall(backoffMs); // always back off after a failure, in either cadence } diff --git a/scripts/remote.sh b/scripts/remote.sh index ddc20f96e..4f4bfe3b3 100644 --- a/scripts/remote.sh +++ b/scripts/remote.sh @@ -2379,9 +2379,19 @@ _remote_status_one() { # useful thing, and "no cycles" beside "engine stopped" reads as a second fault # rather than the same one. if [ "$engine_state" = "running" ]; then - local stamp last_cycle + local stamp last_cycle failures stamp="$(_remote_sync_engine_cycle_stamp "$team")" last_cycle="$(_remote_read_config_field "$stamp" '$.last_success_at')" + # HOW MANY HAVE FAILED SINCE (#829). A success timestamp on its own cannot + # say whether it is the present state: an engine that has failed every cycle + # for six days still holds the last success it ever had, and this line + # printed it with nothing beside it. The machine in that report had not + # synced since the 13th and said "last successful sync 2026-08-13", which + # reads as working. It was found because two rosters disagreed, not here. + failures="$(_remote_read_config_field "$stamp" '$.failures_since_success')" + case "$failures" in + ''|null|0|*[!0-9]*) failures="" ;; + esac if [ -z "$last_cycle" ] || [ "$last_cycle" = "null" ]; then # Says what is absent, not what did not happen. The record is written # best-effort, so its absence covers three states this cannot tell apart: @@ -2390,7 +2400,19 @@ _remote_status_one() { # unrecorded. "nothing has synced yet" picks one of the three and asserts # it -- a claim wider than the check, which is the defect this whole line # exists to remove from `status` rather than to reintroduce. - echo " cycles: no successful cycle recorded since this engine started" + if [ -n "$failures" ]; then + # Two different absences. "Nothing recorded and nothing has failed" is a + # young engine; "nothing recorded and 17 have failed" is an engine that + # has never worked, and only the second is a fault. + echo " cycles: no successful cycle recorded since this engine started; $failures have failed since it did" + else + echo " cycles: no successful cycle recorded since this engine started" + fi + elif [ -n "$failures" ]; then + # The count, not an interpretation of it. Whether one failure is a blip + # and whether two hundred is a broken remote is not decided here -- what + # this line owes the reader is that the timestamp above is not now. + echo " cycles: last successful sync $last_cycle; $failures have failed since" else echo " cycles: last successful sync $last_cycle" fi diff --git a/tests/remote_sync_engine.test.mjs b/tests/remote_sync_engine.test.mjs index 1dfe079fd..c70742742 100644 --- a/tests/remote_sync_engine.test.mjs +++ b/tests/remote_sync_engine.test.mjs @@ -4085,3 +4085,70 @@ test("runLoop: a non-retryable error that is NOT a refusal still ends the loop", eventCall: async () => {}, }), /config is unreadable/); }); + +// THE COUNT IS THE PART THAT SAYS WHETHER THE TIMESTAMP IS NOW (#829). +// +// An engine that failed every cycle for six days kept the last success it ever +// had, and `status` printed it alone. Recording the failures is what lets that +// line stop reading as "working". +const cycleFailureRun = async (script) => { + const failures = []; + let i = 0; + await assert.rejects(() => runLoop(config, {}, { + cycleCall: async () => { + const step = script[i++]; + if (step === undefined) { const stop = new Error("stop"); stop.retryable = false; throw stop; } + if (step === "refuse") { const no = new Error("no"); no.refusal = true; throw no; } + if (step === "fail") { const net = new Error("net"); net.retryable = true; throw net; } + return {}; + }, + sleepCall: async () => {}, + isRetryableCall: (error) => error.retryable === true, + isRefusalCall: (error) => error.refusal === true, + recordRefusalCall: async () => {}, + clearRefusalCall: async () => {}, + eventCall: async () => {}, + nowCall: () => `T${failures.length + 1}`, + recordCycleCall: async () => {}, + recordCycleFailureCall: async (team, at, count) => { failures.push([team, at, count]); }, + }), /stop/); + return failures; +}; + +test("runLoop: failures are counted since the last success, refusals included", async () => { + assert.deepEqual(await cycleFailureRun(["fail", "fail"]), + [[config.local_team, "T1", 1], [config.local_team, "T2", 2]]); + // A REFUSAL COUNTS. It does not advance `consecutiveFailures` -- that drives + // the backoff and a refusal is not evidence the transport is degrading -- but + // it is exactly as much of a "nothing synced" as a timeout is, and #829 was + // six days of nothing but refusals. + assert.deepEqual(await cycleFailureRun(["refuse", "refuse"]), + [[config.local_team, "T1", 1], [config.local_team, "T2", 2]]); + // Mixed, and counted as one run of not-succeeding rather than two. + assert.deepEqual((await cycleFailureRun(["fail", "refuse", "fail"])).map(([, , n]) => n), + [1, 2, 3]); + // A success ends the run: the count answers "since the last success", so it + // starts again from one rather than continuing. + assert.deepEqual((await cycleFailureRun(["fail", "ok", "fail"])).map(([, , n]) => n), [1, 1]); + // And nothing is recorded when nothing fails. + assert.deepEqual(await cycleFailureRun(["ok", "ok"]), []); +}); + +test("runLoop: a failure record that throws does not change the loop", async () => { + // Same promise as the success record, on the path where things are already + // going wrong: bookkeeping must never be the reason a retry does not happen. + let cycles = 0; + await assert.rejects(() => runLoop(config, {}, { + cycleCall: async () => { + cycles += 1; + if (cycles > 2) { const stop = new Error("stop"); stop.retryable = false; throw stop; } + const net = new Error("net"); net.retryable = true; throw net; + }, + sleepCall: async () => {}, + isRetryableCall: (error) => error.retryable === true, + eventCall: async () => {}, + recordCycleCall: async () => {}, + recordCycleFailureCall: async () => { throw new Error("run directory is unwritable"); }, + }), /stop/); + assert.equal(cycles, 3, "a failing record must not stop the loop from retrying"); +}); diff --git a/tests/test_remote_status_liveness.bats b/tests/test_remote_status_liveness.bats index 59b44f956..4c7c58940 100644 --- a/tests/test_remote_status_liveness.bats +++ b/tests/test_remote_status_liveness.bats @@ -861,3 +861,66 @@ write_unownable_ps_fixture() { run bash -c "grep -v '^[[:space:]]*#' \"\$1\" | sed 's/_agmsg_pid_alive_local//g' | grep -c '_agmsg_pid_alive'" _ "$SCRIPTS/remote.sh" [ "$output" = "0" ] } + + +@test "status: a success that is not the present state says so (#829)" { + # The report this exists for: an engine had failed every cycle for six days + # and `status` printed the last success it ever had, with nothing beside it. + # It read as working. The person who found it found it because two rosters + # disagreed -- this line told them nothing. + start_matching_engine + local fake_bin stamp + fake_bin="$(write_matching_ps_fixture)" + stamp="$TEST_SKILL_DIR/run/remote-sync.testteam.cycles.json" + + # A success and nothing else: unchanged, because a working engine must not + # grow a clause about failures it has not had. + printf '%s\n' '{"type":"sync_cycle_stamp","first_success_at":"2026-08-13T09:00:00.000Z","last_success_at":"2026-08-13T09:02:00.000Z"}' > "$stamp" + run env PATH="$fake_bin:$PATH" bash "$SCRIPTS/remote.sh" status testteam + [ "$status" -eq 0 ] + printf '%s\n' "$output" | grep -q -F -- "cycles: last successful sync 2026-08-13T09:02:00.000Z" + refute grep -qF -- "have failed since" <<<"$output" + + # The same success, with failures recorded after it. + printf '%s\n' '{"type":"sync_cycle_stamp","first_success_at":"2026-08-13T09:00:00.000Z","last_success_at":"2026-08-13T09:02:00.000Z","last_failure_at":"2026-08-19T00:00:00.000Z","failures_since_success":6842}' > "$stamp" + run env PATH="$fake_bin:$PATH" bash "$SCRIPTS/remote.sh" status testteam + [ "$status" -eq 0 ] + printf '%s\n' "$output" | grep -q -F -- "cycles: last successful sync 2026-08-13T09:02:00.000Z; 6842 have failed since" +} + +@test "status: a never-successful engine separates young from broken (#829)" { + # "Nothing recorded" covers an engine that started a second ago and one that + # has never completed a cycle in six days. Only the second is a fault, and + # the line said the same thing for both. + start_matching_engine + local fake_bin stamp + fake_bin="$(write_matching_ps_fixture)" + stamp="$TEST_SKILL_DIR/run/remote-sync.testteam.cycles.json" + + [ ! -e "$stamp" ] + run env PATH="$fake_bin:$PATH" bash "$SCRIPTS/remote.sh" status testteam + [ "$status" -eq 0 ] + printf '%s\n' "$output" | grep -q -F -- "cycles: no successful cycle recorded since this engine started" + refute grep -qF -- "have failed since it did" <<<"$output" + + printf '%s\n' '{"type":"sync_cycle_stamp","last_failure_at":"2026-08-19T00:00:00.000Z","failures_since_success":91}' > "$stamp" + run env PATH="$fake_bin:$PATH" bash "$SCRIPTS/remote.sh" status testteam + [ "$status" -eq 0 ] + printf '%s\n' "$output" | grep -q -F -- "91 have failed since it did" +} + +@test "status: a failure count it cannot read is absent, not zero (#829)" { + # The record is written best-effort by the engine, so a truncated or + # half-written file is a state this has to survive. A garbage value must not + # print as a count, and must not take the success line down with it. + start_matching_engine + local fake_bin stamp + fake_bin="$(write_matching_ps_fixture)" + stamp="$TEST_SKILL_DIR/run/remote-sync.testteam.cycles.json" + printf '%s\n' '{"type":"sync_cycle_stamp","last_success_at":"2026-08-13T09:02:00.000Z","failures_since_success":"lots"}' > "$stamp" + run env PATH="$fake_bin:$PATH" bash "$SCRIPTS/remote.sh" status testteam + [ "$status" -eq 0 ] + printf '%s\n' "$output" | grep -q -F -- "cycles: last successful sync 2026-08-13T09:02:00.000Z" + refute grep -qF -- "lots" <<<"$output" + refute grep -qF -- "have failed since" <<<"$output" +}