fleetd #512 (part 1): log a positive completion line when drainAll finishes #522

2026-09-12T06:30:31+02:00

agent commented

2026-09-12 06:30:31 +02:00

fleetd #512, part 1 only (the Java/SessionManager half). Part 2 (the script-side detection in
scripts/redeploy-fleetd.sh) is deliberately left for a separate PR/ticket per the issue's own
scope note, and is being worked by another session in parallel.

Defect

SessionManager.drainAll drained cleanly with no log output at all — both existing log calls
(drainSnapshot's per-session-failure log.warn, and drainAll's straggler-sweep log.warn) sit
on abnormal paths. So a clean drain and a drain that died on the first session were indistinguishable
in the log: neither produced a line. A script trying to detect a dead shutdown drain (the failure
mode is an uncaught exception on a shutdown thread — never goes through the logger, no ERROR token)
had no positive signal to assert on.

Fix

One log.info at the end of drainAll:

drain complete: released={N} abandoned={M} (still BUSY at the shutdown deadline)

Fires on the normal path, including the all-zero case (no members were live) — that must still
print the line, so it isn't gated behind if (released > 0) or similar.
Both drainSnapshot passes (the main snapshot and the post-loop straggler sweep) are folded into
the ONE line, so a caller can't mistake a two-pass drain for two separate drains.
abandoned counts sessions that were still BUSY at the moment they were released — i.e. the
whole-drain deadline passed before they left BUSY on their own.

Design choices

drainSnapshot now returns a small private record DrainTally(released, abandoned) instead of
void, and the two tallies are combined with tally.plus(...). drainAll itself keeps its
void signature — no test or caller needed a wider change.
The private release(String paneId, ReleaseCause cause) overload now returns the removed
MemberSession (was void) so drainSnapshot can read its state() at the moment of removal —
reusing the exact same "was it BUSY when it went?" check that logPreservedForShutdown already
makes for its own WARN line. This overload has exactly one call site (inside drainSnapshot); the
public release(String) overload discards the return value as before, so no other caller needed
a change. Picked this over threading an AtomicInteger/holder through both methods because it
changes fewer signatures and reuses an existing state check instead of duplicating it.
Wording: fixed prefix "drain complete: " for a script to grep on, numbers in released=/
abandoned= placeholders rather than in the prefix.

Suggested grep for the redeploy script (part 2)

grep -c '^.*drain complete: released=' "$FRESH_LOG"

or, to also read the numbers:

grep -oE 'drain complete: released=[0-9]+ abandoned=[0-9]+' "$FRESH_LOG"

Tests

drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain — two READY (non-BUSY) sessions,
asserts released=2 abandoned=0 on the clean path.
drainAllLogsANonZeroAbandonedCountForASessionStillBusyAtTheDeadline — reuses the existing
BUSY/READY fixture from drainAllReleasesBusyAndReadySessionsAndWaitsForBusy (the BUSY session
never leaves BUSY, so the drain spins the full real-time timeout and releases it anyway), asserts
released=2 abandoned=1.
Both pin the shared SessionManager logger to Level.INFO before acting and restore it to
null in finally — an earlier test in the same class (onTurnFailedIsLoggedAtWarnWithThePriorState)
sets that same logger to Level.WARN and never restores it, which silently swallowed the new
log.info on first attempt (caught by running the whole class, not just the new tests in
isolation).

Mutation proof

Mutation A — commented out released++; in drainSnapshot (so the line always reports
released=0):

grep -n 'MUTATION-CB512-A' → present (rc=0); grep -n 'released++;' → absent (rc=1) — the 0/1
pair proving the mutation actually applied, not a shell-expansion false positive.
Ran both new tests: Tests run: 2, Failures: 2, Errors: 0, Skipped: 0, exit 1. Failing assertions:
expected: <true> but was: <false> on drain complete: released=0 abandoned=0 … and
drain complete: released=0 abandoned=1 ….
Restored; shasum -a 256 of SessionManager.java before/after: byte-identical
(d21ecd3adb3f66933e2f248a8ec81a2c324bfee323a3cc30da525842c33ea80a).
Green control: Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, exit 0.

Mutation B — if (false && removed != null && removed.state() == MemberSession.State.BUSY)
(the abandoned branch made unreachable):

grep -n 'MUTATION-CB512-B' → present (rc=0); grep -n for the un-mutated if (removed != null && removed.state() == MemberSession.State.BUSY) { line → absent (rc=1).
Ran the abandoned-count test: Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, exit 1. Failing
assertion: expected: <true> but was: <false> on drain complete: released=2 abandoned=0 ….
Restored; same sha256 as above confirmed byte-identical again.
Green control: Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, exit 0.

Build

mvn -f fleetd/pom.xml clean install — unpiped, redirected to a file, echo $? on its own line:
exit=0. Final aggregate line: Tests run: 1698, Failures: 0, Errors: 0, Skipped: 0. BUILD SUCCESS.

Other silent-on-success teardown paths found in this class (not fixed — separate ticket, per scope)

reapIdle (SessionManager.java): a successfully reaped session is only logged at debug
("reaping idle session …"); the method's own aggregate reap count (its int return value) is
never logged anywhere — its only caller, SessionReaper.loop(), discards it. So a normal reap
sweep — 0 or N sessions reaped — produces no visible (INFO+) log line, only a warn if one
session's release throws. Same shape as the drainAll defect this PR fixes.
releaseRemoved's ordinary-cause path: every plain release (reap, explicit stop, normal
completion) is logged only at debug ("releasing session pane=… cause=…"), while every nearby
abnormal branch (dirty worktree preserved, worktree-remove failure) is warn. At default INFO
level a normal single-session teardown is invisible while any snag in it is loud — narrower than
the drainAll case (this fires per-session, not as an aggregate), but the same asymmetry.

Not touched (out of scope, per the brief)

scripts/redeploy-fleetd.sh — left alone; another worker is editing it for a different ticket,
and #512 part 2 (asserting the grep against this new line) is intentionally a separate PR.

fleetd #512, part 1 only (the Java/SessionManager half). Part 2 (the script-side detection in scripts/redeploy-fleetd.sh) is deliberately left for a separate PR/ticket per the issue's own scope note, and is being worked by another session in parallel. ## Defect `SessionManager.drainAll` drained cleanly with **no log output at all** — both existing log calls (`drainSnapshot`'s per-session-failure `log.warn`, and `drainAll`'s straggler-sweep `log.warn`) sit on abnormal paths. So a clean drain and a drain that died on the first session were indistinguishable in the log: neither produced a line. A script trying to detect a dead shutdown drain (the failure mode is an uncaught exception on a shutdown thread — never goes through the logger, no ERROR token) had no positive signal to assert on. ## Fix One `log.info` at the end of `drainAll`: ``` drain complete: released={N} abandoned={M} (still BUSY at the shutdown deadline) ``` - Fires on the normal path, including the all-zero case (no members were live) — that must still print the line, so it isn't gated behind `if (released > 0)` or similar. - Both `drainSnapshot` passes (the main snapshot and the post-loop straggler sweep) are folded into the ONE line, so a caller can't mistake a two-pass drain for two separate drains. - `abandoned` counts sessions that were still `BUSY` at the moment they were released — i.e. the whole-drain deadline passed before they left `BUSY` on their own. ## Design choices - `drainSnapshot` now returns a small private record `DrainTally(released, abandoned)` instead of `void`, and the two tallies are combined with `tally.plus(...)`. `drainAll` itself keeps its `void` signature — no test or caller needed a wider change. - The private `release(String paneId, ReleaseCause cause)` overload now returns the removed `MemberSession` (was `void`) so `drainSnapshot` can read its `state()` at the moment of removal — reusing the exact same "was it BUSY when it went?" check that `logPreservedForShutdown` already makes for its own WARN line. This overload has exactly one call site (inside `drainSnapshot`); the public `release(String)` overload discards the return value as before, so no other caller needed a change. Picked this over threading an `AtomicInteger`/holder through both methods because it changes fewer signatures and reuses an existing state check instead of duplicating it. - Wording: fixed prefix `"drain complete: "` for a script to grep on, numbers in `released=`/ `abandoned=` placeholders rather than in the prefix. ## Suggested grep for the redeploy script (part 2) ``` grep -c '^.*drain complete: released=' "$FRESH_LOG" ``` or, to also read the numbers: ``` grep -oE 'drain complete: released=[0-9]+ abandoned=[0-9]+' "$FRESH_LOG" ``` ## Tests - `drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain` — two READY (non-BUSY) sessions, asserts `released=2 abandoned=0` on the clean path. - `drainAllLogsANonZeroAbandonedCountForASessionStillBusyAtTheDeadline` — reuses the existing BUSY/READY fixture from `drainAllReleasesBusyAndReadySessionsAndWaitsForBusy` (the BUSY session never leaves BUSY, so the drain spins the full real-time timeout and releases it anyway), asserts `released=2 abandoned=1`. - Both pin the shared `SessionManager` logger to `Level.INFO` before acting and restore it to `null` in `finally` — an earlier test in the same class (`onTurnFailedIsLoggedAtWarnWithThePriorState`) sets that same logger to `Level.WARN` and never restores it, which silently swallowed the new `log.info` on first attempt (caught by running the whole class, not just the new tests in isolation). ### Mutation proof **Mutation A** — commented out `released++;` in `drainSnapshot` (so the line always reports `released=0`): - `grep -n 'MUTATION-CB512-A'` → present (rc=0); `grep -n 'released++;'` → absent (rc=1) — the 0/1 pair proving the mutation actually applied, not a shell-expansion false positive. - Ran both new tests: `Tests run: 2, Failures: 2, Errors: 0, Skipped: 0`, exit 1. Failing assertions: `expected: <true> but was: <false>` on `drain complete: released=0 abandoned=0 …` and `drain complete: released=0 abandoned=1 …`. - Restored; `shasum -a 256` of `SessionManager.java` before/after: byte-identical (`d21ecd3adb3f66933e2f248a8ec81a2c324bfee323a3cc30da525842c33ea80a`). - Green control: `Tests run: 2, Failures: 0, Errors: 0, Skipped: 0`, exit 0. **Mutation B** — `if (false && removed != null && removed.state() == MemberSession.State.BUSY)` (the abandoned branch made unreachable): - `grep -n 'MUTATION-CB512-B'` → present (rc=0); `grep -n` for the un-mutated `if (removed != null && removed.state() == MemberSession.State.BUSY) {` line → absent (rc=1). - Ran the abandoned-count test: `Tests run: 1, Failures: 1, Errors: 0, Skipped: 0`, exit 1. Failing assertion: `expected: <true> but was: <false>` on `drain complete: released=2 abandoned=0 …`. - Restored; same sha256 as above confirmed byte-identical again. - Green control: `Tests run: 1, Failures: 0, Errors: 0, Skipped: 0`, exit 0. ## Build `mvn -f fleetd/pom.xml clean install` — unpiped, redirected to a file, `echo $?` on its own line: exit=0. Final aggregate line: `Tests run: 1698, Failures: 0, Errors: 0, Skipped: 0`. `BUILD SUCCESS`. ## Other silent-on-success teardown paths found in this class (not fixed — separate ticket, per scope) - `reapIdle` (SessionManager.java): a successfully reaped session is only logged at `debug` (`"reaping idle session …"`); the method's own aggregate reap count (its `int` return value) is never logged anywhere — its only caller, `SessionReaper.loop()`, discards it. So a normal reap sweep — 0 or N sessions reaped — produces no visible (INFO+) log line, only a `warn` if one session's release throws. Same shape as the `drainAll` defect this PR fixes. - `releaseRemoved`'s ordinary-cause path: every plain release (reap, explicit stop, normal completion) is logged only at `debug` (`"releasing session pane=… cause=…"`), while every nearby abnormal branch (dirty worktree preserved, worktree-remove failure) is `warn`. At default INFO level a normal single-session teardown is invisible while any snag in it is loud — narrower than the `drainAll` case (this fires per-session, not as an aggregate), but the same asymmetry. ## Not touched (out of scope, per the brief) - `scripts/redeploy-fleetd.sh` — left alone; another worker is editing it for a different ticket, and #512 part 2 (asserting the grep against this new line) is intentionally a separate PR.

agent added 1 commit 2026-09-12 06:30:31 +02:00

fleetd #512 (part 1): log a positive completion line when drainAll finishes

CI / contract (pull_request) Successful in 59s

Details

CI / build (pull_request) Successful in 1m38s

Details

33720c42b3

drainAll used to log nothing on a clean drain — both existing log calls
(drainSnapshot's per-session failure, drainAll's straggler-sweep warning)
sit on abnormal paths, so "drained fine" and "died on the first session"
looked identical: no log line either way.

Add one log.info at the end of drainAll: "drain complete: released=N
abandoned=M (still BUSY at the shutdown deadline)". It fires on the
normal path, including the all-zero case, and folds both drainSnapshot
passes (main snapshot + straggler sweep) into one line.

drainSnapshot now returns a private DrainTally(released, abandoned)
record instead of void, and the private release(paneId, cause) overload
now returns the removed MemberSession (previously void) so drainSnapshot
can read its state at the moment of removal — the same check
logPreservedForShutdown already makes. Both signature changes are
private with a single call site, so the blast radius stays small.

ltms merged commit 37dcefa834 into main

2026-09-12 06:34:52 +02:00

ltms referenced this pull request

2026-09-12 06:35:25 +02:00

A test pins the shared SessionManager logger to WARN and never restores it, so any later test asserting an INFO line silently sees nothing #525

ltms referenced this pull request

2026-09-12 06:35:55 +02:00

redeploy-fleetd.sh says "no ERROR lines since restart" while blind to the exact failure #493 is about #512

agent referenced this issue from a commit

2026-09-12 06:49:10 +02:00

fleetd #525: restore the logger level, not just the appender, in SessionManagerTest

agent referenced this pull request