Merge #522: log a positive drain-completion line when drainAll finishes (fleetd #512 part 1)
CI / contract (push) Successful in 55s
CI / build (push) Successful in 1m36s

Verified by the lead, not taken from the worker's report.

Build run by me, unpiped: exit 0, "Tests run: 1698, Failures: 0, Errors: 0, Skipped: 0",
BUILD SUCCESS. That is +2 on main's 1696, matching the two new tests.

Both merge constraints from the ticket hold, checked against the diff:
- The log.info is the last statement of drainAll's normal path and is NOT in a finally. The only
  finally in the file is at :372, unrelated. So a drain that dies still leaves no line, which is
  the absence signal part 2 will alert on.
- released and abandoned are incremented inside the drainSnapshot loop, not read from a collection
  at the end, so a partial report can never be served by this line.

Mutation check run by me: deleting the completion line makes both new tests fail by name —
drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain and
drainAllLogsANonZeroAbandonedCountForASessionStillBusyAtTheDeadline, "no drain-complete INFO
logged, expected true but was false". Restored byte-identical
(d21ecd3adb3f66933e2f248a8ec81a2c324bfee323a3cc30da525842c33ea80a). So the tests really depend on
the line rather than passing for another reason.

Design accepted: drainSnapshot returns a private DrainTally record and release() returns the
removed session so abandoned can reuse the same BUSY-at-removal check logPreservedForShutdown
makes, instead of a second registry read. Both are private with one call site.

Two follow-ups filed rather than fixed here, see the ticket comments.
This commit was merged in pull request #522.
This commit is contained in:
2026-09-12 06:34:51 +02:00
2 changed files with 136 additions and 5 deletions
@@ -302,9 +302,10 @@ public final class SessionManager implements TurnListener {
* with no copy and no error. Do NOT fuse these back together; the cost of an orphaned worktree
* is a logged path an operator can reclaim, the cost of a deleted one is unrecoverable work.
*/
private void release(String paneId, ReleaseCause cause) {
private MemberSession release(String paneId, ReleaseCause cause) {
MemberSession removed = registry.remove(paneId);
releaseRemoved(paneId, removed, handles.remove(paneId), cause);
return removed;
}
/**
@@ -1064,16 +1065,39 @@ public final class SessionManager implements TurnListener {
* drain (see above), and a straggler must not buy the drain more time than the flag it lost the
* race against would have. In the ordinary case the sweep finds nothing and costs one empty
* {@link #roster()} call.
*
* <p>fleetd #512: a drain that releases every session cleanly used to log nothing at all — the
* only log calls in this method and {@link #drainSnapshot} sit on abnormal paths, so "nothing
* logged" was indistinguishable from "died on the first session". The {@code log.info} at the
* end below is a positive assertion that the drain actually finished, on the normal path,
* every time — including the all-zero case, which is a common and legitimate outcome (no
* members were live) and must still produce the line. Both {@link #drainSnapshot} passes (the
* main snapshot and the straggler sweep) are folded into the one line: a caller reading two
* lines could not tell a two-pass drain from two separate drains.
*/
void drainAll(long timeoutNanos) {
long deadline = System.nanoTime() + timeoutNanos;
draining.set(true);
drainSnapshot(roster(), deadline);
DrainTally tally = drainSnapshot(roster(), deadline);
List<MemberSession> stragglers = roster();
if (!stragglers.isEmpty()) {
log.warn("drain sweep found {} session(s) registered after the drain snapshot was "
+ "taken (raced past the shutdown guard); draining them too", stragglers.size());
drainSnapshot(stragglers, deadline);
tally = tally.plus(drainSnapshot(stragglers, deadline));
}
log.info("drain complete: released={} abandoned={} (still BUSY at the shutdown deadline)",
tally.released(), tally.abandoned());
}
/**
* Running count for one {@link #drainAll} invocation, folded across both {@link #drainSnapshot}
* passes (fleetd #512). {@code abandoned} counts sessions that were still {@code BUSY} at the
* moment they were released — i.e. the whole-drain deadline passed before they left {@code BUSY}
* on their own (see {@link #drainSnapshot}) — a subset of {@code released}, not additional to it.
*/
private record DrainTally(int released, int abandoned) {
private DrainTally plus(DrainTally other) {
return new DrainTally(released + other.released, abandoned + other.abandoned);
}
}
@@ -1081,8 +1105,12 @@ public final class SessionManager implements TurnListener {
* Drain exactly the sessions in {@code snapshot}, waiting out a {@code BUSY} one against the
* shared whole-drain {@code deadline} before releasing it. Shared by {@link #drainAll}'s main
* pass and its post-loop straggler sweep (fleetd #308) so both honor the same one budget.
* Returns how many sessions this pass released, and how many of those were still {@code BUSY}
* (abandoned mid-turn) at the moment of release.
*/
private void drainSnapshot(List<MemberSession> snapshot, long deadline) {
private DrainTally drainSnapshot(List<MemberSession> snapshot, long deadline) {
int released = 0;
int abandoned = 0;
for (MemberSession s : snapshot) {
try {
if (s.state() == MemberSession.State.BUSY) {
@@ -1100,11 +1128,16 @@ public final class SessionManager implements TurnListener {
}
}
}
release(s.paneId(), ReleaseCause.SHUTDOWN);
MemberSession removed = release(s.paneId(), ReleaseCause.SHUTDOWN);
released++;
if (removed != null && removed.state() == MemberSession.State.BUSY) {
abandoned++;
}
} catch (RuntimeException e) {
log.warn("drain failed for pane={}; continuing with remaining sessions", s.paneId(), e);
}
}
return new DrainTally(released, abandoned);
}
/**
@@ -902,6 +902,104 @@ class SessionManagerTest {
.count();
}
/**
* fleetd #512: a drain that releases every session cleanly used to log nothing at all — the
* two log calls in {@code drainAll}/{@code drainSnapshot} both sit on abnormal paths, so
* "clean drain" and "died on the first session" were indistinguishable. This asserts the new
* {@code log.info} line fires on the ordinary, nothing-went-wrong path, and that its numbers
* are the real counts (two released, zero abandoned) rather than just a non-empty string.
*/
@Test
void drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain() {
FakeHerdr herdr = new FakeHerdr();
SessionManager sessions = sessionManager(herdr);
MemberSession first = sessions.acquire("ltms-local", "/one", "/caller", "ownerOne");
MemberSession second = sessions.acquire("ltms-local", "/two", "/caller", "ownerTwo");
sessions.asPresence().markPresent(first.terminalId());
sessions.asPresence().markPresent(second.terminalId());
// Both stay READY — neither is delivered a turn, so neither is BUSY and the drain below
// has nothing abnormal to hit.
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
ch.qos.logback.classic.Logger sessionLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
sessionLog.addAppender(appender);
// Pin INFO explicitly: another test in this class (run order is not guaranteed) leaves the
// shared SessionManager logger pinned at WARN via setLevel and never restores it, which
// would silently swallow the log.info assertion below.
sessionLog.setLevel(Level.INFO);
try {
sessions.drainAll(TimeUnit.MILLISECONDS.toNanos(100));
assertTrue(sessions.roster().isEmpty(), "precondition: the drain actually ran");
String info = appender.list.stream()
.filter(e -> e.getLevel().equals(Level.INFO))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains("drain complete"))
.findFirst()
.orElse("no drain-complete INFO logged");
assertTrue(info.contains("released=2"),
"both released sessions must be counted: " + info);
assertTrue(info.contains("abandoned=0"),
"neither session was BUSY, so nothing was abandoned mid-turn: " + info);
} finally {
sessionLog.detachAppender(appender);
sessionLog.setLevel(null);
}
}
/**
* fleetd #512: the same completion line must also report a non-zero abandoned count when a
* session is still {@code BUSY} once the whole-drain deadline passes — the case the ticket
* calls out as the one a script needs to be able to see. Reuses the same BUSY/READY mix as
* {@link #drainAllReleasesBusyAndReadySessionsAndWaitsForBusy}, which already forces the busy
* session to spin until the real-time deadline expires (its state never leaves BUSY on its
* own), and adds the log assertion that test does not make.
*/
@Test
void drainAllLogsANonZeroAbandonedCountForASessionStillBusyAtTheDeadline() {
FakeHerdr herdr = new FakeHerdr();
SessionManager sessions = sessionManager(herdr);
MemberSession ready = sessions.acquire("ltms-local", "/ready", "/caller", "ownerR");
MemberSession busy = sessions.acquire("ltms-local", "/busy", "/caller", "ownerB");
sessions.asPresence().markPresent(ready.terminalId());
sessions.asPresence().markPresent(busy.terminalId());
sessions.onDelivered(busy.terminalId(), TestTurnTokens.inert(busy.terminalId()));
// busy never leaves BUSY — no completion is delivered — so the drain below must spin the
// full timeout and then release it anyway, counting it abandoned.
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
ch.qos.logback.classic.Logger sessionLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
sessionLog.addAppender(appender);
// Pin INFO explicitly — see the comment in drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain.
sessionLog.setLevel(Level.INFO);
try {
sessions.drainAll(TimeUnit.MILLISECONDS.toNanos(100));
assertTrue(sessions.roster().isEmpty(), "precondition: the drain actually ran");
String info = appender.list.stream()
.filter(e -> e.getLevel().equals(Level.INFO))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains("drain complete"))
.findFirst()
.orElse("no drain-complete INFO logged");
assertTrue(info.contains("released=2"),
"both the ready and the busy session are released: " + info);
assertTrue(info.contains("abandoned=1"),
"the busy session hit the deadline still BUSY and must be counted: " + info);
} finally {
sessionLog.detachAppender(appender);
sessionLog.setLevel(null);
}
}
// --- fleetd #308: a spawn accepted while the shutdown drain is running must not orphan ---
@Test