Bound holds: a timeout, a brake, and no password in the log

A check that hangs no longer stalls every consumer: it times out after
30s and counts as could-not-ask, and the rest of that pass is not asked.
A consumer still not held after being applied again is checked at
doubling intervals up to an hour, and said loudly, so an adapter whose
create and holds disagree costs one re-apply an hour, not one a minute.
The consumer's password is scrubbed from every error the harness logs.

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<string, { times: number; nextAt: number }>();
 
   const applied = new Map<string, string>(); // 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) {
+        } else {
-          // Unable to ask is not evidence of loss. Kept as applied, asked again next time.
+          console.error(
-          console.error(`[provisioner:${resource}] ${g.as}: could not check the backend, will ask again: ${err}`);
+            `[provisioner:${resource}] ${g.as}: still not held after being applied again (${times} times in a row) — ` +
-          continue;
+              `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<Contri
   return (doc.given ?? []).filter((g) => g.as && g.secret);
 }
 
+/** Reject with a timeout error if `p` has not settled within `ms`. */
+function withTimeout<T>(p: Promise<T>, ms: number): Promise<T> {
+  let timer: NodeJS.Timeout | undefined;
+  const timeout = new Promise<never>((_, 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<Record<string, unknown>>): string {
   return JSON.stringify([as, password, values]);
 }

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<boolean>(() => {}),
+      },
+      { 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();