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" +}