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,