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 }); } +});