From d8985719ebfd645afb6052279616d9ae3d368d65 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 12 Sep 2026 11:49:03 +0700 Subject: [PATCH] fleetd #525: restore the logger level, not just the appender, in SessionManagerTest 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: but was: '; 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. --- .../fleet/session/SessionManagerTest.java | 232 ++++++++++-------- 1 file changed, 132 insertions(+), 100 deletions(-) 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 1c94e9e..3e70705 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java @@ -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. + * + *

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 both 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 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 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 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 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 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 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 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 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 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 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,