From 33720c42b3c97d6ac4fb0b6e20c5023bf638f8fc Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 12 Sep 2026 11:29:01 +0700 Subject: [PATCH] fleetd #512 (part 1): log a positive completion line when drainAll finishes MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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/fleet/session/SessionManager.java | 43 +++++++- .../fleet/session/SessionManagerTest.java | 98 +++++++++++++++++++ 2 files changed, 136 insertions(+), 5 deletions(-) diff --git a/fleetd/src/main/java/dev/ltms/fleet/session/SessionManager.java b/fleetd/src/main/java/dev/ltms/fleet/session/SessionManager.java index 9831d32..6fef988 100644 --- a/fleetd/src/main/java/dev/ltms/fleet/session/SessionManager.java +++ b/fleetd/src/main/java/dev/ltms/fleet/session/SessionManager.java @@ -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. + * + *

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 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 snapshot, long deadline) { + private DrainTally drainSnapshot(List 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); } /** diff --git a/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java b/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java index 9eca8fb..1c94e9e 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java @@ -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 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 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 -- 2.52.0