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

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.