fleetd #525: restore the logger level, not just the appender, in SessionManagerTest
CI / contract (pull_request) Successful in 44s
CI / build (pull_request) Successful in 1m53s

The finally block in onTurnFailedIsLoggedAtWarnWithThePriorState (and four other
tests in this file) called setLevel(Level.WARN) on the shared SessionManager
logger (one test used MemberRegistry.class) but only detached the appender in
finally, never restoring the level. Since logback Logger instances are cached
per class and shared across the whole JVM, the pinned level leaked into every
test that ran after it.

Add CapturedLog, a small AutoCloseable that captures a logger's level and
appender together and restores both on close via try-with-resources, so this
shape cannot be half-fixed again. Convert all 7 addAppender/setLevel call
sites in this file to it, including the 2 sites #522 already fixed locally
(kept per-test pinning as belt-and-braces).

Add a proving test (sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn,
@Order(2), running right after the fixed test at @Order(1)) that fails before
this fix and passes after it. Verified with a mutation: dropping the level
restore in CapturedLog.close() turns the proving test red with
'expected: <DEBUG> but was: <WARN>'; restoring is byte-identical to the
pre-mutation file (sha256 matched) and the suite goes green again.

mvn -f fleetd/pom.xml clean install: Tests run: 1699, Failures: 0, Errors: 0,
Skipped: 0. BUILD SUCCESS.
This commit is contained in:
Dai Ha
2026-09-12 11:49:03 +07:00
parent 37dcefa834
commit d8985719eb
@@ -25,7 +25,12 @@ import dev.ltms.fleet.peer.SpawnRequest;
import dev.ltms.fleet.placement.BackendQuarantine;
import dev.ltms.fleet.placement.PlacementDecision;
import dev.ltms.fleet.placement.PlacementPolicies;
import org.junit.jupiter.api.AfterAll;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.MethodOrderer;
import org.junit.jupiter.api.Order;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.TestMethodOrder;
import org.junit.jupiter.api.io.TempDir;
import org.slf4j.LoggerFactory;
@@ -50,9 +55,46 @@ import static org.junit.jupiter.api.Assertions.*;
* CB-301 / CB-303 acceptance tests for the authoritative session registry, one-shot lifecycle FSM,
* and configurable lifecycle limits (idle TTL, context cap, drain).
* No live herdr — everything runs against the same {@link FakeHerdr} the rest of the project uses.
*
* <p>fleetd #525: only {@link #onTurnFailedIsLoggedAtWarnWithThePriorState} (explicitly
* {@link Order#value() @Order(1)}) and the proving test right after it
* ({@link #sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn}, {@code @Order(2)})
* care about method order — every other test here has no {@code @Order} and so runs after both of
* these (JUnit 5's {@link MethodOrderer.OrderAnnotation} gives an unannotated method the lowest
* priority), in whatever relative order it already ran in.
*/
@TestMethodOrder(MethodOrderer.OrderAnnotation.class)
class SessionManagerTest {
/**
* fleetd #525: the level {@link SessionManager}'s logger had when this class started, captured
* before any test here — including the leak this ticket fixes — can touch it. {@code
* pinSessionManagerLoggerToAKnownBaseline} then forces a distinctive, known value (DEBUG) so
* {@link #sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn} can tell "the
* level came back to what it was" apart from "the level happens to already be WARN because
* some earlier test class in this JVM fork (surefire reuses forks by default) left it there" —
* a real risk, since {@code ch.qos.logback.classic.Logger} instances are cached per class and
* shared across the whole JVM, and this exact logger is also touched by
* {@code WorktreeSessionManagerTest#releasePreservesDirtyWorktreeAndLogsWarn}, which has the
* same unfixed leak (reported, not fixed — out of this ticket's scope).
*/
private static Level sessionManagerLevelBeforeThisClass;
@BeforeAll
static void pinSessionManagerLoggerToAKnownBaseline() {
ch.qos.logback.classic.Logger sessionLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class);
sessionManagerLevelBeforeThisClass = sessionLog.getLevel();
sessionLog.setLevel(Level.DEBUG);
}
@AfterAll
static void restoreSessionManagerLoggerLevel() {
ch.qos.logback.classic.Logger sessionLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class);
sessionLog.setLevel(sessionManagerLevelBeforeThisClass);
}
private SessionManager sessionManager(FakeHerdr herdr) {
FleetConfig.Profile cfg = new FleetConfig.Profile(
"ltms-local", "http://gx00.gw:8000", "coder", null, "FLEETD_WORKER_TOKEN",
@@ -81,6 +123,55 @@ class SessionManagerTest {
return new SessionManager(workers, worktrees, clock);
}
/**
* fleetd #525: captures a logger's output and, on {@link #close}, restores <em>both</em> the
* appender and the level to what they were before. A bare {@code addAppender}/{@code
* setLevel} pair whose {@code finally} only detaches the appender leaves the level pinned —
* {@code ch.qos.logback.classic.Logger} instances are cached per class and shared across the
* whole JVM, so a level set by one test in this class is still in effect for every test that
* runs after it, in this class or any other. try-with-resources makes "restored the appender
* but not the level" impossible to write, because there is only one thing to close.
*/
private static final class CapturedLog implements AutoCloseable {
private final ch.qos.logback.classic.Logger logger;
private final Level originalLevel;
private final ListAppender<ILoggingEvent> appender;
private CapturedLog(Class<?> loggerClass, Level pinnedLevel) {
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
this.logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(loggerClass);
this.originalLevel = logger.getLevel();
this.appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
logger.addAppender(appender);
if (pinnedLevel != null) {
logger.setLevel(pinnedLevel);
}
}
/** Capture {@code loggerClass}'s output, pinning its level to {@code pinnedLevel} for the
* duration of the try-with-resources block. */
static CapturedLog at(Class<?> loggerClass, Level pinnedLevel) {
return new CapturedLog(loggerClass, pinnedLevel);
}
/** Capture {@code loggerClass}'s output without changing its level. */
static CapturedLog of(Class<?> loggerClass) {
return new CapturedLog(loggerClass, null);
}
List<ILoggingEvent> events() {
return appender.list;
}
@Override
public void close() {
logger.detachAppender(appender);
logger.setLevel(originalLevel);
}
}
/**
* CB-581: a {@link Worktrees} test double whose {@code hasUncommitted} and {@code remove} can
* be told to throw, so {@link SessionManager#release} can be exercised against exactly the
@@ -466,24 +557,15 @@ class SessionManagerTest {
@Test
void backendErrorForUnknownTargetIsWarnedAndDoesNotCreateASession() {
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);
try {
try (CapturedLog log = CapturedLog.of(SessionManager.class)) {
SessionManager sessions = sessionManager(new FakeHerdr());
assertFalse(sessions.onBackendError("term_missing", "backend exited"));
assertTrue(sessions.roster().isEmpty(), "unknown target must not create a session");
assertTrue(appender.list.stream().anyMatch(e -> e.getLevel().equals(Level.WARN)
assertTrue(log.events().stream().anyMatch(e -> e.getLevel().equals(Level.WARN)
&& e.getFormattedMessage().contains("term_missing")),
"unknown target is logged at WARN");
} finally {
sessionLog.detachAppender(appender);
}
}
@@ -516,19 +598,12 @@ class SessionManagerTest {
}
@Test
@Order(1)
void onTurnFailedIsLoggedAtWarnWithThePriorState() {
// CB-564: this transition used to be a bare DEBUG "session marked failed" — a symptom with no
// cause. A member that can no longer be delegated to must be at least WARN, and should name
// what stage it failed at (here: BUSY, i.e. a turn was in flight and never resolved).
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);
sessionLog.setLevel(Level.WARN);
try {
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.WARN)) {
FakeHerdr herdr = new FakeHerdr();
SessionManager sessions = sessionManager(herdr);
MemberSession session = sessions.acquire("ltms-local", null, "/caller", "term_primary");
@@ -538,18 +613,37 @@ class SessionManagerTest {
sessions.onTurnFailed(terminal);
String warn = appender.list.stream()
String warn = log.events().stream()
.filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage)
.findFirst()
.orElse("no turn-failed WARN logged");
assertTrue(warn.contains(terminal), "the log names the member: " + warn);
assertTrue(warn.contains("BUSY"), "the log names the stage it failed at: " + warn);
} finally {
sessionLog.detachAppender(appender);
}
}
/**
* fleetd #525: proves the leak in {@link #onTurnFailedIsLoggedAtWarnWithThePriorState} above
* (which runs immediately before this, via {@code @Order}) is closed. That test pins the
* shared {@link SessionManager} logger to WARN through a {@link CapturedLog}; if {@link
* CapturedLog#close} only detached the appender — the original bug, before this ticket's fix —
* the level would still read WARN here instead of the {@code DEBUG} baseline this class's
* {@code @BeforeAll} set. Runs at {@code @Order(2)}, guaranteed after {@code @Order(1)} and
* before every other (unannotated) test in this class.
*/
@Test
@Order(2)
void sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn() {
ch.qos.logback.classic.Logger sessionLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class);
assertEquals(Level.DEBUG, sessionLog.getLevel(),
"onTurnFailedIsLoggedAtWarnWithThePriorState pins the shared SessionManager logger "
+ "to WARN; its cleanup must restore the level it captured (DEBUG, set by "
+ "this class's @BeforeAll) rather than leaving WARN pinned for every test "
+ "that runs after it");
}
/**
* fleetd #226: a contended slot is refused through the real {@link SessionManager#acquire}
* path before the real launcher can hand an architect charter to a process.
@@ -576,28 +670,18 @@ class SessionManagerTest {
SessionManager sessions = sessionManager(herdr);
MemberRegistry members = architectRegistry();
sessions.setMemberLifecycle(bindFailureAfterReservation(members));
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
ch.qos.logback.classic.Logger registryLog = (ch.qos.logback.classic.Logger)
LoggerFactory.getLogger(MemberRegistry.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
registryLog.addAppender(appender);
registryLog.setLevel(Level.WARN);
try {
try (CapturedLog log = CapturedLog.at(MemberRegistry.class, Level.WARN)) {
MemberSession session = sessions.acquire("ltms-local", MemberRole.ARCHITECT, null,
"/caller", "term_primary", null);
assertEquals(MemberRole.DEV, session.role(), "a failed reservation bind must use the fallback");
String warn = appender.list.stream()
String warn = log.events().stream()
.filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage)
.findFirst()
.orElse("no slot-exhaustion WARN logged");
assertTrue(warn.contains("ltms-local"), "the WARN names the profile: " + warn);
assertTrue(warn.contains(session.terminalId()), "the WARN names the terminal: " + warn);
} finally {
registryLog.detachAppender(appender);
}
}
@@ -920,22 +1004,14 @@ class SessionManagerTest {
// 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 {
// Pin INFO explicitly: fleetd #525 made CapturedLog itself restore the level it pins, but
// this pin stays anyway as belt-and-braces — a later change to the sweep must not be able
// to make this INFO assertion vacuous again by leaving some other test's WARN pin in place.
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.INFO)) {
sessions.drainAll(TimeUnit.MILLISECONDS.toNanos(100));
assertTrue(sessions.roster().isEmpty(), "precondition: the drain actually ran");
String info = appender.list.stream()
String info = log.events().stream()
.filter(e -> e.getLevel().equals(Level.INFO))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains("drain complete"))
@@ -945,9 +1021,6 @@ class SessionManagerTest {
"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);
}
}
@@ -971,20 +1044,12 @@ class SessionManagerTest {
// 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 {
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.INFO)) {
sessions.drainAll(TimeUnit.MILLISECONDS.toNanos(100));
assertTrue(sessions.roster().isEmpty(), "precondition: the drain actually ran");
String info = appender.list.stream()
String info = log.events().stream()
.filter(e -> e.getLevel().equals(Level.INFO))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains("drain complete"))
@@ -994,9 +1059,6 @@ class SessionManagerTest {
"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);
}
}
@@ -1300,21 +1362,13 @@ class SessionManagerTest {
new WorktreeRequest("cb-581a", null));
worktrees.failHasUncommittedWith(new WorktreeException("git status exited 128"));
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);
sessionLog.setLevel(Level.WARN);
try {
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.WARN)) {
assertDoesNotThrow(() -> sessions.release(s.paneId()),
"a throwing dirty check must not abort the release");
assertTrue(worktrees.removeCalls().isEmpty(),
"the worktree is preserved when its dirty state cannot be determined");
String warn = appender.list.stream()
String warn = log.events().stream()
.filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains(s.worktree()))
@@ -1322,8 +1376,6 @@ class SessionManagerTest {
.orElse("no warn logged naming the worktree");
assertTrue(warn.contains(s.paneId()), "the WARN names the pane: " + warn);
assertTrue(warn.contains(s.terminalId()), "the WARN names the terminal: " + warn);
} finally {
sessionLog.detachAppender(appender);
}
}
@@ -1490,20 +1542,12 @@ class SessionManagerTest {
// this itself, so it no longer propagates out of release() at all.
worktrees.failRemoveFor(b.worktree());
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);
sessionLog.setLevel(Level.WARN);
int reaped;
try {
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.WARN)) {
clock[0] = 100;
reaped = sessions.reapIdle(10);
String warn = appender.list.stream()
String warn = log.events().stream()
.filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains(b.paneId()))
@@ -1511,8 +1555,6 @@ class SessionManagerTest {
.orElse("no worktree-removal-failure WARN logged");
assertTrue(warn.contains(b.terminalId()), "the WARN names the failed session's terminal: " + warn);
assertTrue(warn.contains(b.worktree()), "the WARN names the failed session's worktree: " + warn);
} finally {
sessionLog.detachAppender(appender);
}
assertEquals(3, reaped,
@@ -1558,28 +1600,18 @@ class SessionManagerTest {
// trigger reapIdle's own guard is for, now that #283 closed the worktree-removal trigger.
herdr.paneCloseFailsForPane("w9:pRoot_2", "internal_error");
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);
sessionLog.setLevel(Level.WARN);
int reaped;
try {
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.WARN)) {
clock[0] = 100;
reaped = sessions.reapIdle(10);
String warn = appender.list.stream()
String warn = log.events().stream()
.filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains("reap failed") && m.contains(b.paneId()))
.findFirst()
.orElse("no reap-failed WARN logged for the failing session");
assertTrue(warn.contains(b.terminalId()), "the WARN names the failed session's terminal: " + warn);
} finally {
sessionLog.detachAppender(appender);
}
assertEquals(2, reaped,