row 251: T27 adds its key with -t 2 and sleeps 3.5 s, because ssh-agent counts lifetimes in whole seconds (#453)

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.
This commit is contained in:
jason.woltje committed 2026-10-21 14:12:55 -05:00
1 parent e5e4b2e5af
commit c19b4167ed
2 files changed
+83 -2

No files matched your search

+77
View File
@@ -0,0 +1,77 @@
# 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.
## 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
Not run yet.
+6 -2
View File
@@ -468,8 +468,12 @@ test('T27: ssh-add -t drops the key from an agent the test keeps alive', async (
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'), 1);
await addKey(sock, readFileSync(join(dir, 'k'), 'utf8'), 2);
mark('addKey resolved');
const list = (name) => {
mark(name);
@@ -481,7 +485,7 @@ test('T27: ssh-add -t drops the key from an agent the test keeps alive', async (
};
const first = list('first list');
assert.match(first, /SHA256:/, `first list got ${JSON.stringify(first)}: ${timing()}`);
await sleep(2500);
await sleep(3500);
const second = list('second list');
assert.match(second, /no identities/, `second list got ${JSON.stringify(second)}: ${timing()}`);
});