fleet/fleetd
3
0
Fork 0
Code Issues 73 Pull Requests Actions Packages Projects Releases 1 Wiki Activity

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

Merged
ltms merged 1 commits from worker/512-drain-complete-line-7edd71-3 into main 2026-09-12 06:34:52 +02:00
Conversation 0 Commits 1 Files Changed 2
+136 -5
2 changed files with 136 additions and 5 deletions
Download Patch File Download Diff File Expand all files Collapse all files
fleetd/src/main/java/dev/ltms/fleet/session/SessionManager.java
+38 -5
View File
@@ -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);
}
/**
fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java
+98
View File
@@ -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