A secret that will never be readable stops calling itself a race (hq issue 225)

The harness says 'secret not readable yet' when it cannot open a consumer's
sealed credential, which is true and ordinary on the first pass. It said it
4330 times in three hours on the control machine while two consumers were
never provisioned, because a permission the host will never grant reads
exactly like a file that has not arrived.

After about a minute it says so plainly instead, once and then rarely, and
names what to look at: who owns the file and who this process runs as. The
ownership itself is the controller's to fix.

0.1.9.

package-lock.json

@@ -1,12 +1,12 @@
 {
   "name": "@novox/mesh-sdk",
-  "version": "0.1.8",
+  "version": "0.1.9",
   "lockfileVersion": 3,
   "requires": true,
   "packages": {
     "": {
       "name": "@novox/mesh-sdk",
-      "version": "0.1.8",
+      "version": "0.1.9",
       "devDependencies": {
         "@types/node": "^22.0.0",
         "typescript": "^5.6.0"

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@novox/mesh-sdk",
-  "version": "0.1.8",
+  "version": "0.1.9",
   "description": "The stable spine a Novox Mesh module's own code builds against.",
   "type": "module",
   "exports": {

src/provisioner/index.ts

@@ -77,6 +77,15 @@ export interface ProvisionerOptions {
 /** The longest a consumer whose `create` keeps failing to satisfy `holds` waits between checks. */
 const MAX_BACKOFF_MS = 60 * 60_000;
 
+/** How many passes a secret may be unreadable before the harness stops calling it a race. At the
+ *  default cadence this is about a minute, which is longer than the host takes to write a file
+ *  and far shorter than the three hours issue 225 went unread. */
+const patiently = 12;
+
+/** Once it is saying so loudly, how often to repeat it. Rare enough to stay readable, often
+ *  enough that somebody arriving at the log finds it. */
+const loudlyEvery = 240;
+
 /** One entry in the mesh's contributions file: a consumer the provider must serve. */
 interface Contribution {
   readonly as: string;
@@ -107,6 +116,9 @@ export function runProvisioner(resource: string, adapter: Adapter, opts: Provisi
   // login (`as`) -> what was last applied: the hash that says whether it changed, and the
   // derivation to hand back on withdrawal, which by then is no longer in the file.
   const applied = new Map<string, { hash: string; derived: Readonly<Record<string, unknown>> }>();
+  // How many passes each consumer's secret has been unreadable for, so the wait can stop sounding
+  // like a wait.
+  const waiting = new Map<string, number>();
   let stopped = false;
 
   async function reconcile(): Promise<void> {
@@ -127,9 +139,29 @@ export function runProvisioner(resource: string, adapter: Adapter, opts: Provisi
       } catch (err) {
         // The contribution names a secret the host has not written yet — a normal race on the
         // first pass. Skipped, retried on the next tick, never fatal.
-        console.error(`[provisioner:${resource}] ${g.as}: secret not readable yet (${g.secret}): ${err}`);
+        //
+        // **"Yet" stops being true, and then the word is the fault** (novox/hq issue 225). A
+        // permission the host will never grant reads exactly like a file that has not arrived,
+        // and the two want opposite responses: one is waiting, the other is a person. Said the
+        // patient way while it is plausibly a race, and then said plainly, once, and from then
+        // on only occasionally — because a line repeated every five seconds is a line nobody
+        // reads. Three hours of "not readable yet" is how a provider that served nobody looked
+        // healthy.
+        const n = (waiting.get(g.as) ?? 0) + 1;
+        waiting.set(g.as, n);
+        if (n <= patiently) {
+          console.error(`[provisioner:${resource}] ${g.as}: secret not readable yet (${g.secret}): ${err}`);
+        } else if (n === patiently + 1 || n % loudlyEvery === 0) {
+          console.error(
+            `[provisioner:${resource}] ${g.as}: CANNOT READ the secret after ${n} attempts ` +
+              `(${g.secret}): ${err}. This is not a race any more — nothing has been provisioned ` +
+              `for this consumer and nothing will be until somebody looks. Check who owns the ` +
+              `file and who this process runs as (novox/hq issue 225)`,
+          );
+        }
         continue;
       }
+      waiting.delete(g.as);
       const h = hash(g.as, password, g.values ?? {}, g.derived ?? {});
       const p: Provision = {
         as: g.as, password, values: g.values ?? {}, derived: g.derived ?? {}, at: g.at, consumer: g.node,

test/sdk.test.ts

@@ -123,6 +123,43 @@ test("provisioner hands the adapter what the mesh derived, and still has it at w
   stop();
 });
 
+test("provisioner stops calling an unreadable secret a race, and says what to look at", async () => {
+  // novox/hq issue 225. A permission the host will never grant reads exactly like a file that has
+  // not arrived yet, and three hours of "not readable yet" is how a provider that served nobody
+  // looked healthy. After a while the wording has to change, because the word "yet" is the fault.
+  const dir = await mkdtemp(join(tmpdir(), "prov-unreadable-"));
+  const receives = join(dir, "db.json");
+  await writeFile(
+    receives,
+    JSON.stringify({
+      contributions: 1, requirement: "db",
+      given: [{ from: "photos", node: "anchor", as: "mesh_anchor_photos",
+                secret: join(dir, "never-written.secret"), values: {} }],
+    }),
+  );
+
+  const said: string[] = [];
+  const wasError = console.error;
+  console.error = (line: unknown) => { said.push(String(line)); };
+  let stop: (() => void) | undefined;
+  try {
+    stop = runProvisioner("db", { async create() {}, async remove() {} }, { receives, everyMs: 5 });
+    await waitFor(() => said.some((l) => l.includes("CANNOT READ")), 3000);
+  } finally {
+    stop?.();
+    console.error = wasError;
+  }
+
+  const patient = said.filter((l) => l.includes("not readable yet"));
+  const loud = said.filter((l) => l.includes("CANNOT READ"));
+  assert.ok(patient.length > 0, "it never gave the host a chance to write the file");
+  assert.ok(patient.length <= 12, `it called a permanent refusal a race ${patient.length} times`);
+  assert.ok(loud.length > 0, "it never stopped calling it a race");
+  // And the loud one says where to look, because the answer is ownership and not the mesh.
+  assert.ok(loud[0].includes("who owns the file"), `the loud line does not say what to check: ${loud[0]}`);
+  assert.ok(loud[0].includes("issue 225"), "the loud line does not name the record");
+});
+
 test("provisioner applies again what the backend no longer holds, and trusts memory without holds", async () => {
   const dir = await mkdtemp(join(tmpdir(), "prov-holds-"));
   await writeFile(join(dir, "webapp.secret"), "minted-pw\n");