row 251: BUILD.md slot results, part A reds at the predicted fractions only, fix 18/18, bus suite green 3 times and concurrently (sage-2154)

ssh-agent sets a key's death to whole seconds of CLOCK_BOOTTIME plus the lifetime and reaps on the
same whole seconds (OpenSSH 10.5p1 ssh-agent.c:1315, :1064, misc.c:1828), so -t 1 can end within
milliseconds of an add made late in a second. -t 2 keeps the key over 1 s; the sleep keeps its 1.5 s
margin past the 2 s ceiling. Both checks stay. host-run.mjs is unchanged: production adds with
timeout + 30. Evidence and the slot plan are in agents/darkwing/work/queue-251/BUILD.md.

agents/darkwing/work/queue-251/BUILD.md

@@ -0,0 +1,191 @@
+# Row 251 build: T27 lists no identities right after `ssh-add -t 1` (Vikunja #453)
+
+Brief `docs/plans/2026-10-21_t27-ssh-add-lifetime.md` (rev 2931), Mos ruling mos-1185 item 2, assigned in
+sage-2075. Owner Darkwing, reviewer Dewey, gate owner Sage. Branch `darkwing/row251` from 3b0aef995,
+claimed in-progress at rev 2938.
+
+## Step 1: the failure names its cause (e5e4b2e5a)
+
+T27's two lists now carry a message that prints only when they fail. It gives the time from addKey's
+start to its resolve and to each `ssh-add -l` call, the hrtime at each with how far into its second it
+fell, `/proc/uptime` at each, and whether the agent process and its socket were still there. The checks
+themselves did not change. The commit holds nothing else.
+
+## Step 2: the cause
+
+ssh-agent counts a key's lifetime in whole seconds of CLOCK_BOOTTIME, at the add and at the reap. I read
+OpenSSH 10.5p1, the version on dragon-lin (`ssh -V`: OpenSSH_10.5p1), at tag V_10_5_P1 (ssh-agent.c
+sha256 873691c4, misc.c sha256 ee467f43):
+
+- `misc.c:1790-1798` and `:1828`: `monotime()` returns `ts.tv_sec` of `clock_gettime(CLOCK_BOOTTIME)`,
+  falling back to MONOTONIC. The fraction of the second is dropped.
+- `ssh-agent.c:1315`: the `-t` constraint sets `*deathp = monotime() + seconds`. Lines 1410 and 1598
+  do the same for the agent's default lifetime.
+- `ssh-agent.c:1064`: the reaper drops a key when `now >= id->death`, `now` being `monotime()` again.
+- `ssh-agent.c:2650`: the main loop runs `reaper()` after every poll, before it reads requests. A list
+  that arrives after the boundary sees the key gone.
+
+So a key added at second s plus a fraction f dies at s + N, and `-t N` keeps it N - f seconds, between
+N - 1 and N. With `-t 1`, an add late in a second leaves the key milliseconds to live. That matches
+Sage's probe in the brief: 8 of 80 `-t 1` adds missed, each one made at 0.9947-0.9973 of a monotonic
+second and finished at 0.998-0.0008, and none earlier in the second missed. It also matches proof 5's
+failure, where the first list ran 31.9 ms into the test and found no identities.
+
+Node's hrtime is CLOCK_MONOTONIC. BOOTTIME differs from it by the time the host spent suspended. On
+dragon-lin the difference read 0.000001 s at 19:09Z, so a monotonic second boundary is a BOOTTIME one
+here.
+
+`addKey` and the agent start are not the cause. `addKey` passes the lifetime through as `-t`
+(`host-run.mjs:90`), and the agent starts with no default lifetime (`:175`). Production adds the key
+with `timeout + 30` (`:180`), where losing up to a second makes no difference. The only caller that
+can't afford the lost fraction is T27, which asks for 1 s. The fix belongs in the test's lifetime choice,
+and `host-run.mjs` doesn't change.
+
+The slot confirms this against T27 itself (below), not just from the source.
+
+## Step 3: the fix (this commit)
+
+T27 adds the key with `-t 2`. The agent then keeps it more than 1 s and at most 2 s. The first list
+runs milliseconds after the add, so it has over a second of margin even under load. The sleep before
+the second list grows from 2.5 s to 3.5 s, which keeps the old 1.5 s margin past the new 2 s ceiling.
+Both checks stay: listed after the add, gone after the lifetime. A comment above the add says why the
+lifetime is 2.
+
+I considered `-t 3` with a 4.5 s sleep for a 2 s floor. One second of floor is far above anything the
+first list has needed (31.9 ms in proof 5), and the concurrent-suite run below tests it under load, so I
+took the smaller change.
+
+## Base
+
+The branch stays on 3b0aef995. By 19:15Z origin/refactor was at 6096b051b, after rows 66 and 243
+landed. `git diff 3b0aef995 6096b051b` touches neither `packages/bus/src/host-run.mjs` nor
+`packages/bus/tests/host-run.test.mjs`, so there's no rebase (sage-2084). Row 243 did change
+`packages/bus/tests/process.test.mjs`. My slot's bus suites run that file as it was at 3b0aef995, and the
+gate rerun on Sage's slot runs it as landed.
+
+## Prediction for part A on e5e4b2e5a (written before the slot)
+
+The hook starts `ssh-add -t 1` at the given fraction of a monotonic second. From the brief's probe, the
+agent stores the key about 3 ms later. The first list reaches the agent a few ms after addKey resolves:
+Node's exit event, the mark, and `ssh-add -l`'s own start. A red needs the add to land before the second
+boundary and the list to land after it.
+
+- 0.990: green. The add and the list both land before the boundary.
+- 0.993, 0.995, 0.996, 0.997: red expected. The add lands before the boundary, the list after. At 0.993
+  and 0.997 I'm less sure, because the list (at 0.993) or the add (at 0.997) can land right at the
+  boundary. A green at either is in line with the cause, and so is a red.
+- 0.998: green. The add lands after the boundary, so the key gets almost a full second.
+
+Every red should show "first list got" an answer with no SHA256 line. It should also show addKey
+resolving before a second boundary and the first list starting after it or within a few ms of it, with
+the agent alive and its socket present.
+
+Under sage-2084's rule, on e5e4b2e5a only a red at 0.990 or 0.998 counts toward the stop, and two such
+reds stop the run. On the fix commit any red counts, and two stop it. In parts B to D, the first red stops
+the run.
+
+## Slot plan
+
+All scripts are in `/mnt/storage/scratch/darkwing-251-out/`, launched from `/`, each behind the busy
+checks and chained with `&&`, TMPDIR under `/mnt/storage/scratch/tmp`.
+
+1. Confirmation. `align-hooks.mjs` is a load hook, outside the repo, that serves `host-run.mjs` with
+   `addKey` wrapped to start `ssh-add` at a chosen fraction of a monotonic second. T27 runs unchanged
+   under it, alone (`--test-name-pattern`). It runs at fractions 0.990, 0.993, 0.995, 0.996, 0.997 and
+   0.998, three times each:
+   - on e5e4b2e5a (step 1, `-t 1`). Expected: some first lists fail, and the step 1 message shows the
+     add's resolve and the list on either side of a second boundary, with the agent alive and the
+     socket present. These reds are the point of the run.
+   - on the fix commit (`-t 2`). Expected: all 18 pass.
+2. `host-run.test.mjs` whole, once, on the fix commit.
+3. The bus suite whole, three times in a row.
+4. The bus suite whole in two clean worktrees at the same commit, started together.
+
+## Slot results
+
+Sage's CLEAR came in sage-2154 at 20:58:55Z. `slot-251.sh` ran parts A and B from 20:59:22Z to 21:01:33Z,
+on node v26.8.1 and OpenSSH_10.5p1, with TMPDIR `/mnt/storage/scratch/tmp/r251`. At the start, BOOTTIME
+minus MONOTONIC read 0.000001 s, then 0.000000 s twice (dewey-0769 N1). So the hrtime fractions below
+put the agent's second boundary in the right place.
+
+### Part A: T27 alone under `align-hooks.mjs`, 3 runs per fraction
+
+The fraction is when the hook started `ssh-add`. The hook logged each start within 0.0001 of its target.
+
+| fraction | e5e4b2e5a (`-t 1`) | 68f2dfd4b (`-t 2`) |
+|---|---|---|
+| 0.990 | 3 pass | 3 pass |
+| 0.993 | 3 pass | 3 pass |
+| 0.995 | 3 red | 3 pass |
+| 0.996 | 3 red | 3 pass |
+| 0.997 | 3 pass | 3 pass |
+| 0.998 | 3 pass | 3 pass |
+
+e5e4b2e5a went red 6 times out of 18, every time at a fraction the prediction named, so none of them
+counted toward the stop. 68f2dfd4b passed all 18. The fix runs used 68f2dfd4b, whose test blob is the same
+as c19b4167e's (280132c7).
+
+Every red failed on the first list and got `"The agent has no identities.\n"`, with the agent alive and
+its socket present. The step 1 message gave these hrtime fractions. "addKey start" is the mark before the
+hook's wait, so its fraction is earlier than the ssh-add start.
+
+| run | addKey resolved | first list mark |
+|---|---|---|
+| 0.995 rep 1 | 0.9992 (+317.6 ms) | 0.9993 |
+| 0.995 rep 2 | 0.9991 (+846.5 ms) | 0.9991 |
+| 0.995 rep 3 | 0.9988 (+845.0 ms) | 0.9988 |
+| 0.996 rep 1 | 0.9999 (+839.8 ms) | 1.0000 |
+| 0.996 rep 2 | 0.0004 (+845.0 ms) | 0.0004 |
+| 0.996 rep 3 | 0.0002 (+835.9 ms) | 0.0002 |
+
+At 0.995 the add finished about 4 ms in, before the boundary, and the list mark came just before it. The
+`ssh-add -l` process then reached the agent after the boundary. At 0.996 the agent stored the key before
+the boundary, and addKey resolved just after it. In both cases the key's whole second ended between the
+add and the list, which is the cause step 2 gives. The two edge fractions came out green on the first
+build. At 0.993 the list still reached the agent before the boundary, and at 0.997 the add landed after
+it, so the key got almost a full second. The prediction allowed either result at those two.
+
+### Part B: `host-run.test.mjs` whole on 68f2dfd4b
+
+24 tests, 24 passed (21:01:18Z, 14.0 s).
+
+### The stop before C1, and the resume
+
+At 21:01:33Z the script stopped before C1, with exit 4 and no red. My own `busy.sh` matched two `sleep 60`
+processes, mine, in `darkwing-r251/packages/bus`. Part B left them. They come from T27 "the start sweep
+keeps a live bus dir and kills only a matching live process" (`host-run.test.mjs:528` and `:536`). Its
+`t.after` SIGKILLs the `/bin/sh -c 'sleep 60; :'` parent, but the `sleep` child lives on for up to 60 s.
+That code is outside this row's diff, so the row leaves it alone, and it's recorded below as a follow-up.
+Sage confirmed (sage-2159) that the right move is to resume only the scope that hadn't run.
+
+`slot-251-cd.sh` runs C and D as `slot-251.sh` has them, with the same two busy checks. Before each check,
+it waits up to 75 s for those orphans to exit: my uid, my trees, a command line of exactly `sleep 60`.
+It logs them as it waits. Any other process still trips the checks.
+
+### Parts C and D: the bus suite whole on 68f2dfd4b
+
+| run | start | tests | pass | fail | time |
+|---|---|---|---|---|---|
+| C1 | 21:02:48Z | 598 | 598 | 0 | 21.6 s |
+| C2 | 21:04:06Z | 598 | 598 | 0 | 21.4 s |
+| C3 | 21:05:26Z | 598 | 598 | 0 | 22.1 s |
+| D1, darkwing-r251 | 21:06:44Z | 598 | 598 | 0 | 24.2 s |
+| D2, darkwing-r251b, TMPDIR `r251-b` | 21:06:44Z | 598 | 598 | 0 | 24.2 s |
+
+The script waited 33 s before C2, 34 s before C3, 33 s before D and 32 s before the sweep. Each time it
+was waiting for that run's `sleep 60` orphans (two per suite, four after D), and nothing else. After the
+wait, the sweep of my trees, the out dir and TMPDIR found 0 processes left (21:08:04Z). Sage confirmed
+(sage-2159, sage-2160) that the short gitea-api and `node --check` runs they made during the slot weren't
+stops. None of my busy checks refused on any of them.
+
+These runs used the bus files as they were at 3b0aef995. Since then, origin/refactor (666173292, then
+7247d80c7 and c3d88840c with row 196) has changed `broker.mjs`, `runtime.mjs` and `server.mjs`, which T27's
+file imports, along with other bus files. None of those commits touch this row's two paths or
+`host-run.mjs`, and `git merge-tree` of c3d88840c with 68f2dfd4b is clean. The gate rerun in
+a clean worktree on Sage's slot runs T27 against them.
+
+### Follow-up, not in this row
+
+T27's start-sweep test leaves the `sleep 60` child of each planted shell running for up to 60 s after
+the test. Killing the process group (`process.kill(-pid)`; both shells are spawned `detached`) or
+`exec sleep 60` in the shell would end the child along with its parent.

packages/bus/tests/host-run.test.mjs

@@ -458,17 +458,36 @@ test('T27: ssh-add -t drops the key from an agent the test keeps alive', async (
   const agent = spawn('ssh-agent', ['-D', '-a', sock], { stdio: 'ignore' });
   t.after(() => agent.kill('SIGKILL'));
   assert.ok(await until(() => existsSync(sock)));
-  await addKey(sock, readFileSync(join(dir, 'k'), 'utf8'), 1);
-  const list = () => {
+  // A failed list names its cause: when each step ran on the monotonic clock (hrtime) and on
+  // /proc/uptime (CLOCK_BOOTTIME, which ssh-agent's lifetime counts in whole seconds), and
+  // whether the agent and its socket were still there.
+  const marks = [];
+  const mark = (name) => marks.push({ name, ns: process.hrtime.bigint(), uptime: readFileSync('/proc/uptime', 'utf8').split(' ')[0] });
+  const timing = () => {
+    const at = (m) => `${m.name} +${(Number(m.ns - marks[0].ns) / 1e6).toFixed(1)} ms (hrtime ${(Number(m.ns % 1_000_000_000n) / 1e9).toFixed(4)} s into its second, uptime ${m.uptime})`;
+    const alive = agent.exitCode === null && agent.signalCode === null;
+    return `${marks.map(at).join('; ')}; agent ${alive ? 'alive' : `gone (${agent.exitCode ?? agent.signalCode})`}, socket ${existsSync(sock) ? 'present' : 'missing'}`;
+  };
+  // ssh-agent sets a key's death to the whole second of CLOCK_BOOTTIME at the add plus the
+  // lifetime, and drops it once that whole second is reached. So `-t N` keeps a key between N - 1
+  // and N seconds: `-t 1` added just before a second boundary was gone within milliseconds (#453).
+  // `-t 2` keeps it at least 1 s, and the sleep waits past the 2 s ceiling.
+  mark('addKey start');
+  await addKey(sock, readFileSync(join(dir, 'k'), 'utf8'), 2);
+  mark('addKey resolved');
+  const list = (name) => {
+    mark(name);
     try {
       return execFileSync('ssh-add', ['-l'], { env: { PATH: '/usr/bin:/bin', SSH_AUTH_SOCK: sock }, encoding: 'utf8' });
     } catch (e) {
       return e.stdout;
     }
   };
-  assert.match(list(), /SHA256:/);
-  await sleep(2500);
-  assert.match(list(), /no identities/);
+  const first = list('first list');
+  assert.match(first, /SHA256:/, `first list got ${JSON.stringify(first)}: ${timing()}`);
+  await sleep(3500);
+  const second = list('second list');
+  assert.match(second, /no identities/, `second list got ${JSON.stringify(second)}: ${timing()}`);
 });
 
 // The test's own limit makes a hung addKey (M37a, M37b) fail in seconds, not at the batch timeout.