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