From 312d6407046df7a27feaf09db2ef275a54158b95 Mon Sep 17 00:00:00 2001 From: Jean-Baptiste Date: Tue, 8 Sep 2026 14:30:38 +0200 Subject: [PATCH] fix(remote): back off exponentially per host instead of retrying at a fixed cadence A dead host previously reran the ssh inventory every fixed interval forever; one field log carries 226 identical "transport disposed" warnings, one every 300.0 s, over ~19 h with nothing ever slowing it down or surfacing it. refreshNow() now tracks consecutive failures per alias and delays the next attempt by min(intervalMs * 2^(failures-1), 30 min): base equals the host's own configured cadence so an isolated blip costs nothing extra, and 30 min was chosen as a ceiling short enough that a recovered host is picked back up without anyone restarting the app. A host past its next-attempt instant is skipped for that cycle only, no ssh call, no log line, while its peers still run on schedule. One success resets the counter and delay to nominal immediately. Decision: a permanently failing host is only slowed to the 30 min ceiling, never disabled, disabling would need the same enabled flag Settings owns, turning a transient network problem into a silent, permanent loss of mirroring with no UI to notice or undo it, whereas one capped attempt per 30 min is cheap enough to just keep paying. Failure logging is throttled to the first failure and each change of tier, not every attempt. Per-host state (consecutive failures, last error, next attempt instant) is readable via getRemoteHostState(alias). Refs #215 --- .ai/contexts/session-cache.md | 27 ++++++ remote-index.js | 66 +++++++++++++- test/remote-index.test.js | 166 ++++++++++++++++++++++++++++++++++ 3 files changed, 257 insertions(+), 2 deletions(-) diff --git a/.ai/contexts/session-cache.md b/.ai/contexts/session-cache.md index f698cd7b..e2c74e72 100644 --- a/.ai/contexts/session-cache.md +++ b/.ai/contexts/session-cache.md @@ -142,6 +142,33 @@ or deleted from here. silently forgotten. `remote-index.js` catches per host, so one dead host does not stop its peers or the local scan. +- **A host that keeps failing backs off per host, exponentially, capped at + 30 min — it is never disabled (issue #215).** Field incident 2026-09-07/08: + a `transport disposed` cause (fixed separately) reran the plain fixed-cadence + loop every 300.0 s for ~19 h (226 identical `refresh failed` warnings) because + nothing slowed a permanently broken host down. `refreshNow()` now tracks + `{ failures, lastError, nextAttemptAt }` per alias; on failure the delay is + `min(intervalMs * 2^(failures-1), 30 min)` — base equals the host's own + configured cadence, so an isolated blip costs nothing extra, and the 30 min + ceiling was chosen so an operator never has to restart the app to get a + recovered host picked back up. A host past `nextAttemptAt` is skipped for + that cycle only: no ssh call, no log line, and its peers still run on + schedule — the loop `continue`s per host, it never returns early. One + success resets `failures`/`nextAttemptAt` to nominal immediately (issue + requirement: fast recovery, not a cool-down after the outage ends). + **Decision: slow down, never disable.** Disabling would need to flip the + same `enabled` flag the Settings UI owns, which is out of this issue's scope + and would turn a transient network problem into a silent, permanent loss of + mirroring that nothing in the sidebar currently surfaces — the capped + exponential delay already bounds the cost of a dead host to one attempt per + 30 min, which is cheap enough to just keep trying. Logging is throttled to + the first failure and each change of tier (`onHostFailure` in + `remote-index.js`), not every attempt, so the same field incident would have + produced roughly 5 lines instead of 226. Per-host state is readable via + `getRemoteHostState(alias)` (mirrors `getRemoteSessions(alias)`); no GUI + reads it yet. Proven in `test/remote-index.test.js` with an injected + `now()` clock — no real timers, no `setTimeout` waits. + - **The mirror is indexed off the main thread.** `workers/scan-projects.js` takes `folderPrefix` and a `folders` subset in `workerData`, and `sessionCache.scanFoldersViaWorker` writes each folder result through the same diff --git a/remote-index.js b/remote-index.js index d8371a6f..b93816fa 100644 --- a/remote-index.js +++ b/remote-index.js @@ -14,6 +14,9 @@ const { syncMirror } = require('./remote-mirror'); const NOOP_LOG = { info() {}, warn() {}, error() {} }; +// see .ai/contexts/session-cache.md ("Remote hosts backoff") +const MAX_BACKOFF_MS = 30 * 60 * 1000; + /** * Periodic mirror + index of every declared SSH host. * see .ai/contexts/session-cache.md ("Remote SSH hosts") @@ -30,16 +33,63 @@ const NOOP_LOG = { info() {}, warn() {}, error() {} }; * notify() -> push a sidebar refresh * timers -> { setInterval, clearInterval } (test seam) * sync -> syncMirror override (test seam) + * now() -> current epoch ms (test seam, defaults to Date.now) */ function createRemoteIndexer(ctx) { const log = ctx.log || NOOP_LOG; const timers = ctx.timers || { setInterval, clearInterval }; const sync = ctx.sync || syncMirror; + const now = ctx.now || Date.now; let timer = null; let inFlight = false; let stopped = false; const remoteSessions = new Map(); // alias -> sessions array, from the same ssh cycle as the inventory + const hostBackoff = new Map(); // alias -> { failures, lastError, nextAttemptAt } + + function backoffState(alias) { + let s = hostBackoff.get(alias); + if (!s) { + s = { failures: 0, lastError: null, nextAttemptAt: 0 }; + hostBackoff.set(alias, s); + } + return s; + } + + // see .ai/contexts/session-cache.md ("Remote hosts backoff") + function backoffDelayMs(failures, intervalMs) { + if (failures <= 0) return 0; + return Math.min(intervalMs * Math.pow(2, failures - 1), MAX_BACKOFF_MS); + } + + function onHostSuccess(alias) { + const state = backoffState(alias); + if (state.failures > 0) { + log.info(`[remote:${alias}] refresh recovered after ${state.failures} consecutive failure(s)`); + } + state.failures = 0; + state.lastError = null; + state.nextAttemptAt = 0; + } + + function onHostFailure(alias, err, intervalMs) { + const state = backoffState(alias); + const prevDelay = backoffDelayMs(state.failures, intervalMs); + state.failures += 1; + state.lastError = err.message; + const delay = backoffDelayMs(state.failures, intervalMs); + state.nextAttemptAt = now() + delay; + if (delay !== prevDelay) { + log.warn(`[remote:${alias}] refresh failed (${state.failures}x consecutive): ${err.message}; ` + + `retrying in ${Math.round(delay / 1000)}s`); + } + } + + function getRemoteHostState(alias) { + const s = hostBackoff.get(alias); + if (!s) return { consecutiveFailures: 0, lastError: null, nextAttemptAt: 0 }; + return { consecutiveFailures: s.failures, lastError: s.lastError, nextAttemptAt: s.nextAttemptAt }; + } function hosts() { return enabledHosts(ctx.getHosts ? ctx.getHosts() : []); @@ -66,6 +116,9 @@ function createRemoteIndexer(ctx) { for (const alias of [...remoteSessions.keys()]) { if (!known.has(alias)) remoteSessions.delete(alias); } + for (const alias of [...hostBackoff.keys()]) { + if (!known.has(alias)) hostBackoff.delete(alias); + } return dropped; } @@ -140,15 +193,19 @@ function createRemoteIndexer(ctx) { inFlight = true; let changed = pruneUnknownAliases(list) > 0; const errors = []; + const intervalMs = normalizeRefreshMs(ctx.getRefreshMs ? ctx.getRefreshMs() : undefined); try { for (const host of list) { if (stopped) break; + const state = backoffState(host.alias); + if (now() < state.nextAttemptAt) continue; // still backing off: no attempt, no log, no ssh try { if (await refreshHost(host)) changed = true; + onHostSuccess(host.alias); } catch (err) { remoteSessions.set(host.alias, []); errors.push({ alias: host.alias, error: err.message }); - log.warn(`[remote:${host.alias}] refresh failed: ${err.message}`); + onHostFailure(host.alias, err, intervalMs); } } } finally { @@ -197,7 +254,12 @@ function createRemoteIndexer(ctx) { return remoteSessions.get(alias) || []; } - return { start, stop, dispose, restart, refreshNow, isRunning: () => timer !== null, getRemoteSessions }; + return { + start, stop, dispose, restart, refreshNow, + isRunning: () => timer !== null, + getRemoteSessions, + getRemoteHostState, + }; } module.exports = { createRemoteIndexer }; diff --git a/test/remote-index.test.js b/test/remote-index.test.js index 135c2b76..2676f4e2 100644 --- a/test/remote-index.test.js +++ b/test/remote-index.test.js @@ -32,6 +32,14 @@ function fakeTimers() { }; } +/** A controllable clock for the backoff seam (`ctx.now`) — no wall-clock wait. */ +function fakeClock(start = 0) { + let t = start; + const fn = () => t; + fn.advance = (ms) => { t += ms; }; + return fn; +} + test('no host declared: no timer, no transport call, no mirror directory', async () => { const dataDir = tmp('idx-none'); try { @@ -332,3 +340,161 @@ test('dispose() is terminal: it stops the timer and ends the transport', async ( assert.equal(indexer.isRunning(), false, 'shutdown must clear the timer'); } finally { fs.rmSync(dataDir, { recursive: true, force: true }); } }); + +// Issue #215 acceptance: a host stuck in `ssh inventory failed ... transport +// disposed` must not be retried at a fixed cadence forever (the field log +// shows 226 identical attempts, one every 300.0 s, over ~19 h). Backoff is +// driven by an injected clock (`ctx.now`), never a real timer. + +test('consecutive failures on one host back off exponentially and the delay is capped', async () => { + const dataDir = tmp('idx-backoff-space'); + try { + const clock = fakeClock(0); + let attempts = 0; + const BASE = 60_000; + const CAP = 30 * 60 * 1000; + const indexer = createRemoteIndexer({ + getHosts: () => [{ alias: 'dead' }], + getRefreshMs: () => BASE, + dataDir, + transport: {}, + scanFolders: () => Promise.resolve({ ok: true }), + listIndexedFolderKeys: () => [], + timers: fakeTimers(), + now: clock, + sync: async () => { attempts++; throw new Error('ssh inventory failed (exit -1): transport disposed'); }, + }); + + const expectedDelay = (failures) => Math.min(BASE * 2 ** (failures - 1), CAP); + + for (let failures = 1; failures <= 8; failures++) { + await indexer.refreshNow(); + const state = indexer.getRemoteHostState('dead'); + assert.equal(state.consecutiveFailures, failures, `failure ${failures} counted`); + assert.equal(state.nextAttemptAt - clock(), expectedDelay(failures), `delay after failure ${failures}`); + + // A tick before the backoff elapses must not spend another ssh attempt. + const before = attempts; + clock.advance(1); + await indexer.refreshNow(); + assert.equal(attempts, before, `failure ${failures}: not due yet, must be skipped`); + + // Land exactly on the next due instant for the following iteration. + clock.advance(state.nextAttemptAt - clock()); + } + + assert.equal(attempts, 8, 'every due cycle actually attempted the host once'); + assert.equal(expectedDelay(8), CAP, 'sanity: by the 8th failure the exponential has saturated at the cap, ' + + 'so the per-iteration assertion above already proved the ceiling holds'); + } finally { fs.rmSync(dataDir, { recursive: true, force: true }); } +}); + +test('a success after consecutive failures resets the backoff to nominal immediately', async () => { + const dataDir = tmp('idx-backoff-reset'); + try { + const clock = fakeClock(0); + let shouldFail = true; + const indexer = createRemoteIndexer({ + getHosts: () => [{ alias: 'flaky' }], + getRefreshMs: () => 60_000, + dataDir, + transport: {}, + scanFolders: () => Promise.resolve({ ok: true }), + listIndexedFolderKeys: () => [], + timers: fakeTimers(), + now: clock, + sync: async () => { + if (shouldFail) throw new Error('ssh: connect to host flaky port 22: timed out'); + return { fetched: 0, unchanged: 0, removed: 0, failed: 0, total: 0, changedFolders: new Set() }; + }, + }); + + // Three consecutive failures widen the gap well past the nominal cadence. + let failedState; + let delayBeforeRecovery; + for (let i = 0; i < 3; i++) { + await indexer.refreshNow(); + failedState = indexer.getRemoteHostState('flaky'); + delayBeforeRecovery = failedState.nextAttemptAt - clock(); + clock.advance(delayBeforeRecovery); + } + assert.equal(failedState.consecutiveFailures, 3); + assert.equal(delayBeforeRecovery, 240_000, 'the 3rd failure widened the delay past the 60 s nominal cadence'); + + // The host recovers on the next due attempt. + shouldFail = false; + await indexer.refreshNow(); + const recovered = indexer.getRemoteHostState('flaky'); + assert.equal(recovered.consecutiveFailures, 0, 'failure count drops to zero on success'); + assert.equal(recovered.lastError, null, 'the stale error is cleared'); + assert.equal(recovered.nextAttemptAt, 0, 'no artificial delay is left behind after recovery'); + + // Immediately eligible again — no leftover cool-down from the outage. + shouldFail = true; // if backoff state had survived, this would silently be skipped + const r = await indexer.refreshNow(); + assert.equal(r.errors.length, 1, 'the very next cycle actually attempted the host again'); + } finally { fs.rmSync(dataDir, { recursive: true, force: true }); } +}); + +test('a host backing off does not block its peers from refreshing on schedule', async () => { + const dataDir = tmp('idx-backoff-isolation'); + try { + const clock = fakeClock(0); + const aliveCalls = []; + const indexer = createRemoteIndexer({ + getHosts: () => [{ alias: 'dead' }, { alias: 'alive' }], + getRefreshMs: () => 60_000, + dataDir, + transport: {}, + scanFolders: () => Promise.resolve({ ok: true }), + listIndexedFolderKeys: () => [], + timers: fakeTimers(), + now: clock, + sync: async ({ alias }) => { + if (alias === 'dead') throw new Error('ssh: dead unreachable'); + aliveCalls.push(clock()); + return { fetched: 0, unchanged: 0, removed: 0, failed: 0, total: 0, changedFolders: new Set() }; + }, + }); + + await indexer.refreshNow(); // dead fails once (60 s backoff), alive succeeds + assert.equal(aliveCalls.length, 1); + assert.equal(indexer.getRemoteHostState('dead').consecutiveFailures, 1); + + // Advance far less than dead's backoff: dead must be skipped, alive must not. + clock.advance(1_000); + const r = await indexer.refreshNow(); + assert.equal(aliveCalls.length, 2, 'alive is refreshed on every cycle regardless of dead backing off'); + assert.equal(indexer.getRemoteHostState('dead').consecutiveFailures, 1, 'dead was skipped, not re-attempted'); + assert.equal(r.errors.length, 0, 'a skipped host is not reported as a fresh error'); + } finally { fs.rmSync(dataDir, { recursive: true, force: true }); } +}); + +test('failure logging is throttled: only the first failure and tier changes are logged', async () => { + const dataDir = tmp('idx-backoff-log'); + try { + const clock = fakeClock(0); + const warnings = []; + const indexer = createRemoteIndexer({ + getHosts: () => [{ alias: 'dead' }], + getRefreshMs: () => 60_000, + dataDir, + transport: {}, + scanFolders: () => Promise.resolve({ ok: true }), + listIndexedFolderKeys: () => [], + log: { info() {}, warn: (m) => warnings.push(m), error() {} }, + timers: fakeTimers(), + now: clock, + sync: async () => { throw new Error('ssh inventory failed (exit -1): transport disposed'); }, + }); + + for (let i = 0; i < 12; i++) { + await indexer.refreshNow(); + clock.advance(indexer.getRemoteHostState('dead').nextAttemptAt - clock()); + } + + assert.equal(indexer.getRemoteHostState('dead').consecutiveFailures, 12, '12 attempts actually happened'); + assert.ok(warnings.length < 12, 'not every attempt is logged'); + assert.ok(warnings.length <= 6, `only the tier changes are logged, got ${warnings.length}`); + } finally { fs.rmSync(dataDir, { recursive: true, force: true }); } +});