The idle reaper destroys a member's pane, worktree, ticket and report and logs nothing at info — while the refs sweep beside it reports its count #530

Open
opened 2026-09-12 07:35:06 +02:00 by ltms · 0 comments
Owner

Reported as two unverified follow-ups by the #522 worker. I have now checked both in the code myself. Both are real, and together they are worse than either one alone.

All measurements on main at a6415f3.

1. reapIdle's count is computed and then thrown away

SessionManager.reapIdle logs each reaped session at debug, logs a failure at warn, and returns a count:

log.debug("reaping idle session terminal={} pane={}: idle {}s exceeds the {}s ttl", …)
log.warn("reap failed for pane={} terminal={} worktree={}; continuing with …", …)
return reaped;

SessionReaper.loop() at :65 calls it and discards the return:

sessions.reapIdle(idleTtlNanos);

grep -n 'reapIdle' in SessionReaper.java returns that one line. Nothing logs the count.

2. The ordinary release path is debug-only while every abnormal sibling is warn

In SessionManager.releaseRemoved (lines 329-400), counted by level:

Level Count What
log.debug 1 "releasing session pane={} terminal={} state={} cause={}" — the ordinary release
log.warn 2 the dirty-worktree preserve (CB-576) and the "could not tell if dirty" fallback (CB-581)
log.info 0 —

So the normal teardown is invisible above debug, and only the two abnormal outcomes are visible. SessionManager has 4 log.info calls in total (:465 snapshot ref, :521 shutdown-drain worktree preserve, :1071 a javadoc mention, :1088 #522's new drain-complete line) — every one of them on the shutdown or snapshot paths. None on idle reap.

Why the combination is the defect

An idle reap is destructive. When lifecycle.idleTtlSeconds elapses, the reaper releases the member: the pane closes, the ticket expires, the worker's report becomes unrecoverable, and unless the worktree is dirty the worktree is removed too.

At info level, that entire event produces no output at all. The only trace is a debug line per session and a discarded count.

The asymmetry that makes this indefensible is inside the same class. SessionReaper.loop() runs two sweeps:

:65   sessions.reapIdle(idleTtlNanos);                       // count discarded
:90   log.info("refs/wip retention sweep deleted {} snapshot ref(s) older than 24h whose …", …)

The sweep that deletes git refs reports its count at info. The sweep that destroys panes, worktrees, tickets and reports reports nothing. Whichever level is right, these two cannot both be right.

This has already cost me a verification mid-flight

While verifying #518 earlier today, the worktree 05bf45-1 vanished underneath me. It was the idle reaper: the TTL elapsed and it took the worktree along with the pane. Nothing was lost only because the branch was already pushed — luck plus the implementer skill, not a guarantee. The same reap against an uncommitted worktree is the CB-576 data-loss incident, and CB-576's fix is precisely the log.warn above, which fires only when the work happens to be dirty.

From the outside the event is silent and indistinguishable from a member that simply finished. There is no line to search for afterwards, so "did something reap my worktree?" cannot be answered from the log at default level.

This is the "what does an operator see when this happens?" question, applied to a destructive action rather than a failure. It is the same gap as #512: the behaviour is correct and the evidence does not exist.

Asked for

  1. Log the idle reap at info when it reaps anything. One line per sweep, not per session, carrying the count — the same shape as the refs/wip line beside it. A sweep that reaps nothing should stay silent; do not add a per-tick info line.
  2. Use reapIdle's return value in SessionReaper.loop(), or explain in a comment why it is deliberately ignored. Right now it reads as an oversight because it is one.
  3. Raise the per-session release line for a reap that removes a worktree. An operator needs to be able to find out which worktree was removed and when. Keep the ordinary, worktree-less release at debug — the goal is not to make every teardown loud, it is to make a destructive teardown findable. Say in your report which cases you raised and which you left.
  4. Do not put the new line in a finally. It must be reachable only from the path that actually completed the reap, for the same reason #522's drain-complete line is the last statement of drainAll and not in a finally. A line that prints after a partial reap, with whatever count it had, destroys the signal and adds a confident wrong number.

Acceptance

  • mvn -f fleetd/pom.xml clean install exits 0. Quote the Tests run / Failures / Errors / Skipped line verbatim. Do not pipe the command — a pipe hides a failure behind a zero exit; redirect to a file and echo $? on its own line. Note this repo nests fleetd/: there is no POM at the worktree root.
  • A test asserting the info line is present after a reap that removes a worktree, and asserting the count it carries is the number actually reaped — a literal, not a value recomputed the way the production code computes it. If the assertion could be satisfied by an expression equal to the implementation's by construction, it proves nothing; say so rather than writing it.
  • A test asserting no info line is emitted when a sweep reaps nothing.
  • Mutation gate. Make the reap do its work and skip the new line; show the test red, quote the assertion and the exit code, restore, confirm byte-identical with shasum -a 256, then a green control run. Prove the mutation applied with two greps using different search strings, each with a control against a pristine copy.
  • A killed mutation needs no separate harness-proof cell — the kill proves the cell can go red. Only a surviving mutant needs one, and then run it before writing anything about what the survival means.
  • Beware the shared-logger trap, which is live in exactly this area. SessionManager's logger is shared JVM-wide and surefire reuses forks; WorktreeSessionManagerTest:267-272 pins it to WARN and never restores it, which is enough to make an INFO assertion silently see nothing. Use the CapturedLog helper in SessionManagerTest (PR #527) rather than a bare setLevel. #529 is moving it to a shared utility — if that has merged by the time you start, use the shared one. This is not hypothetical: it already made two of #512's assertions vacuous.

Related

  • #512 / #522 — the same "correct behaviour, no evidence" gap, on shutdown drain.
  • #529 — the shared-logger leak that will silently break your INFO assertion if you do not pin the level.
  • CB-576 — the data-loss incident whose fix is the only currently-visible reap outcome.
Reported as two unverified follow-ups by the #522 worker. I have now checked both in the code myself. Both are real, and together they are worse than either one alone. All measurements on `main` at `a6415f3`. ## 1. `reapIdle`'s count is computed and then thrown away `SessionManager.reapIdle` logs each reaped session at **debug**, logs a failure at **warn**, and returns a count: ``` log.debug("reaping idle session terminal={} pane={}: idle {}s exceeds the {}s ttl", …) log.warn("reap failed for pane={} terminal={} worktree={}; continuing with …", …) return reaped; ``` `SessionReaper.loop()` at `:65` calls it and **discards the return**: ```java sessions.reapIdle(idleTtlNanos); ``` `grep -n 'reapIdle'` in `SessionReaper.java` returns that one line. Nothing logs the count. ## 2. The ordinary release path is debug-only while every abnormal sibling is warn In `SessionManager.releaseRemoved` (lines 329-400), counted by level: | Level | Count | What | |---|---|---| | `log.debug` | 1 | `"releasing session pane={} terminal={} state={} cause={}"` — **the ordinary release** | | `log.warn` | 2 | the dirty-worktree preserve (CB-576) and the "could not tell if dirty" fallback (CB-581) | | `log.info` | **0** | — | So the normal teardown is invisible above debug, and only the two *abnormal* outcomes are visible. `SessionManager` has 4 `log.info` calls in total (`:465` snapshot ref, `:521` shutdown-drain worktree preserve, `:1071` a javadoc mention, `:1088` #522's new drain-complete line) — every one of them on the shutdown or snapshot paths. None on idle reap. ## Why the combination is the defect An idle reap is **destructive**. When `lifecycle.idleTtlSeconds` elapses, the reaper releases the member: the pane closes, the ticket expires, the worker's report becomes unrecoverable, and unless the worktree is dirty **the worktree is removed too**. At info level, that entire event produces **no output at all**. The only trace is a debug line per session and a discarded count. The asymmetry that makes this indefensible is inside the same class. `SessionReaper.loop()` runs two sweeps: ``` :65 sessions.reapIdle(idleTtlNanos); // count discarded :90 log.info("refs/wip retention sweep deleted {} snapshot ref(s) older than 24h whose …", …) ``` **The sweep that deletes git refs reports its count at info. The sweep that destroys panes, worktrees, tickets and reports reports nothing.** Whichever level is right, these two cannot both be right. ## This has already cost me a verification mid-flight While verifying #518 earlier today, the worktree `05bf45-1` vanished underneath me. It was the idle reaper: the TTL elapsed and it took the worktree along with the pane. Nothing was lost only because the branch was already pushed — luck plus the `implementer` skill, not a guarantee. The same reap against an *uncommitted* worktree is the CB-576 data-loss incident, and CB-576's fix is precisely the `log.warn` above, which fires only when the work happens to be dirty. From the outside the event is silent and indistinguishable from a member that simply finished. There is no line to search for afterwards, so "did something reap my worktree?" cannot be answered from the log at default level. This is the "what does an operator **see** when this happens?" question, applied to a destructive action rather than a failure. It is the same gap as #512: the behaviour is correct and the evidence does not exist. ## Asked for 1. **Log the idle reap at info when it reaps anything.** One line per sweep, not per session, carrying the count — the same shape as the refs/wip line beside it. A sweep that reaps nothing should stay silent; do not add a per-tick info line. 2. **Use `reapIdle`'s return value** in `SessionReaper.loop()`, or explain in a comment why it is deliberately ignored. Right now it reads as an oversight because it is one. 3. **Raise the per-session release line for a reap that removes a worktree.** An operator needs to be able to find out which worktree was removed and when. Keep the ordinary, worktree-less release at debug — the goal is not to make every teardown loud, it is to make a *destructive* teardown findable. Say in your report which cases you raised and which you left. 4. **Do not put the new line in a `finally`.** It must be reachable only from the path that actually completed the reap, for the same reason #522's drain-complete line is the last statement of `drainAll` and not in a `finally`. A line that prints after a partial reap, with whatever count it had, destroys the signal and adds a confident wrong number. ## Acceptance - `mvn -f fleetd/pom.xml clean install` exits 0. Quote the `Tests run / Failures / Errors / Skipped` line verbatim. Do not pipe the command — a pipe hides a failure behind a zero exit; redirect to a file and `echo $?` on its own line. Note this repo nests `fleetd/`: there is no POM at the worktree root. - **A test asserting the info line is present after a reap that removes a worktree**, and asserting the count it carries is the number actually reaped — a literal, not a value recomputed the way the production code computes it. If the assertion could be satisfied by an expression equal to the implementation's by construction, it proves nothing; say so rather than writing it. - **A test asserting no info line is emitted when a sweep reaps nothing.** - **Mutation gate.** Make the reap do its work and skip the new line; show the test red, quote the assertion and the exit code, restore, confirm byte-identical with `shasum -a 256`, then a green control run. Prove the mutation applied with two greps using **different** search strings, each with a control against a pristine copy. - A killed mutation needs no separate harness-proof cell — the kill proves the cell can go red. Only a **surviving** mutant needs one, and then run it before writing anything about what the survival means. - **Beware the shared-logger trap, which is live in exactly this area.** `SessionManager`'s logger is shared JVM-wide and surefire reuses forks; `WorktreeSessionManagerTest:267-272` pins it to `WARN` and never restores it, which is enough to make an INFO assertion silently see nothing. Use the `CapturedLog` helper in `SessionManagerTest` (PR #527) rather than a bare `setLevel`. #529 is moving it to a shared utility — if that has merged by the time you start, use the shared one. This is not hypothetical: it already made two of #512's assertions vacuous. ## Related - #512 / #522 — the same "correct behaviour, no evidence" gap, on shutdown drain. - #529 — the shared-logger leak that will silently break your INFO assertion if you do not pin the level. - CB-576 — the data-loss incident whose fix is the only currently-visible reap outcome.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#530