Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 46 additions & 0 deletions scripts/internal/remote-sync.mjs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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;
Expand All @@ -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.
//
Expand Down Expand Up @@ -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
}
Expand Down
26 changes: 24 additions & 2 deletions scripts/remote.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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
Expand Down
67 changes: 67 additions & 0 deletions tests/remote_sync_engine.test.mjs
Original file line number Diff line number Diff line change
Expand Up @@ -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");
});
63 changes: 63 additions & 0 deletions tests/test_remote_status_liveness.bats
Original file line number Diff line number Diff line change
Expand Up @@ -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"
}
Loading