diff --git a/src/provisioner/index.ts b/src/provisioner/index.ts index 2a97a40..54113eb 100644 --- a/src/provisioner/index.ts +++ b/src/provisioner/index.ts @@ -54,8 +54,14 @@ export interface ProvisionerOptions { * applied consumer. Defaults to 60000: slower than reconciling, because it reads the backend for * every consumer, and fast enough that a lost login is back within a minute. */ verifyEveryMs?: number; + /** How long one `holds` may take before it counts as "could not ask". Defaults to 30000: the + * loop is sequential, so a check that hangs would otherwise stop every consumer's provisioning. */ + holdsTimeoutMs?: number; } +/** The longest a consumer whose `create` keeps failing to satisfy `holds` waits between checks. */ +const MAX_BACKOFF_MS = 60 * 60_000; + /** One entry in the mesh's contributions file: a consumer the provider must serve. */ interface Contribution { readonly as: string; @@ -74,7 +80,13 @@ export function runProvisioner(resource: string, adapter: Adapter, opts: Provisi const receives = opts.receives ?? envOrThrow("MESH_RECEIVES"); const everyMs = opts.everyMs ?? 5000; const verifyEveryMs = opts.verifyEveryMs ?? 60_000; + const holdsTimeoutMs = opts.holdsTimeoutMs ?? 30_000; let verifiedAt = 0; + // Consumers the backend reported lost, and how many times in a row. A `create` that succeeded and + // is still not held on the next check will never be: something in the adapter disagrees with + // itself. Each repeat doubles the wait before asking again, so such a bug costs one re-apply an + // hour rather than one a minute, and it is said loudly rather than quietly repeated. + const lost = new Map(); const applied = new Map(); // login (`as`) -> hash of what was last applied let stopped = false; @@ -83,7 +95,7 @@ export function runProvisioner(resource: string, adapter: Adapter, opts: Provisi const given = await readContributions(receives, resource); const wantByAs = new Map(given.map((g) => [g.as, g])); // On this pass, ask the backend rather than memory whether each applied consumer is still there. - const verifying = adapter.holds !== undefined && Date.now() - verifiedAt >= verifyEveryMs; + let verifying = adapter.holds !== undefined && Date.now() - verifiedAt >= verifyEveryMs; if (verifying) verifiedAt = Date.now(); // Create or update every consumer whose login, password or values changed. @@ -104,21 +116,39 @@ export function runProvisioner(resource: string, adapter: Adapter, opts: Provisi const p: Provision = { as: g.as, password, values: g.values ?? {}, at: g.at, consumer: g.node }; if (applied.get(g.as) === h) { if (!verifying) continue; + const brake = lost.get(g.as); + if (brake && Date.now() < brake.nextAt) continue; try { - if (await adapter.holds!(p)) continue; + if (await withTimeout(adapter.holds!(p), holdsTimeoutMs)) { + lost.delete(g.as); + continue; + } + } catch (err) { + // Unable to ask is not evidence of loss. Kept as applied, asked again next time. The rest + // of this pass is not asked either: a backend that cannot answer for one consumer will not + // answer for the next, and each would cost a timeout. + console.error(`[provisioner:${resource}] ${g.as}: could not check the backend, will ask again: ${scrub(err, password)}`); + verifying = false; + continue; + } + const times = (brake?.times ?? 0) + 1; + const waitMs = Math.min(MAX_BACKOFF_MS, verifyEveryMs * 2 ** (times - 1)); + lost.set(g.as, { times, nextAt: Date.now() + waitMs }); + if (times === 1) { // Said, because it means the backend lost something while nothing was looking. console.error(`[provisioner:${resource}] ${g.as}: the backend no longer holds it; applying again`); - } catch (err) { - // Unable to ask is not evidence of loss. Kept as applied, asked again next time. - console.error(`[provisioner:${resource}] ${g.as}: could not check the backend, will ask again: ${err}`); - continue; + } else { + console.error( + `[provisioner:${resource}] ${g.as}: still not held after being applied again (${times} times in a row) — ` + + `create does not produce what holds checks; applying again, next check in ${Math.round(waitMs / 1000)}s`, + ); } } try { await adapter.create(p); applied.set(g.as, h); } catch (err) { - console.error(`[provisioner:${resource}] ${g.as}: create failed, will retry: ${err}`); + console.error(`[provisioner:${resource}] ${g.as}: create failed, will retry: ${scrub(err, password)}`); } } @@ -130,6 +160,7 @@ export function runProvisioner(resource: string, adapter: Adapter, opts: Provisi try { await adapter.remove({ as }); applied.delete(as); + lost.delete(as); } catch (err) { console.error(`[provisioner:${resource}] ${as}: remove failed, will retry: ${err}`); } @@ -179,6 +210,24 @@ async function readContributions(path: string, resource: string): Promise g.as && g.secret); } +/** Reject with a timeout error if `p` has not settled within `ms`. */ +function withTimeout(p: Promise, ms: number): Promise { + let timer: NodeJS.Timeout | undefined; + const timeout = new Promise((_, reject) => { + timer = setTimeout(() => reject(new Error(`no answer within ${ms}ms`)), ms); + }); + return Promise.race([p, timeout]).finally(() => clearTimeout(timer)); +} + +/** An error as text with the consumer's password removed, raw and URL-encoded: a failed command's + * message can carry its arguments, and this log is not a place a password may appear. */ +function scrub(err: unknown, password: string): string { + let text = String(err); + if (!password) return text; + for (const form of new Set([password, encodeURIComponent(password)])) text = text.split(form).join("***"); + return text; +} + function hash(as: string, password: string, values: Readonly>): string { return JSON.stringify([as, password, values]); } diff --git a/test/sdk.test.ts b/test/sdk.test.ts index cc8d4c1..4bb8906 100644 --- a/test/sdk.test.ts +++ b/test/sdk.test.ts @@ -167,6 +167,111 @@ test("provisioner keeps a consumer applied when the backend cannot be asked", as stop(); }); +test("provisioner backs off when create does not satisfy holds, and says so", async () => { + const dir = await mkdtemp(join(tmpdir(), "prov-brake-")); + await writeFile(join(dir, "webapp.secret"), "minted-pw"); + const receives = join(dir, "cache.json"); + await writeFile(receives, JSON.stringify({ requirement: "cache", given: [{ as: "webapp-anchor", secret: join(dir, "webapp.secret") }] })); + let creates = 0; + let asked = 0; + const logged: string[] = []; + const original = console.error; + console.error = (...a: unknown[]) => logged.push(a.join(" ")); + try { + const stop = runProvisioner( + "cache", + { + async create() { + creates++; + }, + async remove() {}, + async holds() { + asked++; + return false; // an adapter that disagrees with itself: nothing create does is ever held + }, + }, + { receives, everyMs: 5, verifyEveryMs: 20 }, + ); + await new Promise((r) => setTimeout(r, 400)); + stop(); + } finally { + console.error = original; + } + // Without the brake this would be ~20 creates (one per 20ms check). With doubling waits + // (20, 40, 80, 160ms…) it is a handful. + assert.ok(creates >= 3 && creates <= 7, `creates: ${creates}`); + assert.equal(asked, creates - 1); + assert.ok(logged.some((l) => l.includes("create does not produce what holds checks"))); +}); + +test("provisioner treats a failed or hung holds as could-not-ask, and never logs the password", async () => { + const dir = await mkdtemp(join(tmpdir(), "prov-timeout-")); + await writeFile(join(dir, "a.secret"), "s3cret-pw"); + await writeFile(join(dir, "b.secret"), "other-pw"); + const receives = join(dir, "cache.json"); + await writeFile( + receives, + JSON.stringify({ requirement: "cache", given: [{ as: "a", secret: join(dir, "a.secret") }, { as: "b", secret: join(dir, "b.secret") }] }), + ); + let creates = 0; + const askedFor: string[] = []; + const logged: string[] = []; + const original = console.error; + console.error = (...a: unknown[]) => logged.push(a.join(" ")); + try { + const stop = runProvisioner( + "cache", + { + async create() { + creates++; + }, + async remove() {}, + holds(p) { + askedFor.push(p.as); + // "a" fails the way a shelled-out tool does, with its arguments in the message. + if (p.as === "a") return Promise.reject(new Error(`Command failed: tool --password ${p.password}`)); + return Promise.resolve(true); + }, + }, + { receives, everyMs: 5, verifyEveryMs: 30, holdsTimeoutMs: 20 }, + ); + await new Promise((r) => setTimeout(r, 200)); + stop(); + } finally { + console.error = original; + } + assert.equal(creates, 2); // the first pass only; nothing is applied again on "could not ask" + // After one consumer's check fails, the rest of that pass is not asked: "b" follows "a" and is + // never reached, because every pass stops at "a". + assert.ok(askedFor.length >= 2 && askedFor.every((as) => as === "a"), askedFor.join(",")); + assert.ok(logged.some((l) => l.includes("Command failed: tool --password ***"))); + assert.ok(!logged.some((l) => l.includes("s3cret-pw"))); + + // A check that never answers counts as could-not-ask once its time is up. + let hungCreates = 0; + const hungLogged: string[] = []; + console.error = (...a: unknown[]) => hungLogged.push(a.join(" ")); + try { + const stopHung = runProvisioner( + "cache", + { + async create() { + hungCreates++; + }, + async remove() {}, + holds: () => new Promise(() => {}), + }, + { receives, everyMs: 5, verifyEveryMs: 30, holdsTimeoutMs: 20 }, + ); + await new Promise((r) => setTimeout(r, 200)); + stopHung(); + } finally { + console.error = original; + } + assert.equal(hungCreates, 2); + assert.ok(hungLogged.some((l) => l.includes("no answer within 20ms"))); +}); + test("modules can SERVE: a real async tool, loaded and invoked over the broker", async () => { resetTools();