From 8ea5c2bb1f2c1bb25b389723baa756df677bee47 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 12 Sep 2026 12:48:49 +0700 Subject: [PATCH] fleetd #529: promote CapturedLog to a shared test helper, close the logger-level leak ch.qos.logback.classic.Logger instances are cached per class and shared for the whole JVM, and surefire reuses forks. A test that pins a shared logger's level and restores only the appender leaves that level pinned for every test that runs after it, in the same class or a different one in the same fork. Move CapturedLog (merged in #527 for #525) out of SessionManagerTest into dev.ltms.fleet.testing.CapturedLog, and convert all 19 unrestored setLevel pins across 9 files to it, so there is exactly one way to capture and pin a logger in this test tree: - FleetdAwaitHerdrTest, FleetdReplyInboxSelectionTest, AuditLogTest, CompletionResolverTest, InjectorTest (4), LeadRolloverTest, AmqpConnectionFailureLoggerTest, GitWorktreesTest (8), WorktreeSessionManagerTest. AuditLog logs through a named "audit" logger rather than a class, so CapturedLog gains String-named at()/of() overloads alongside the existing Class-based ones, plus a setLevel() method so a fixture that already pinned a coarser baseline (GitWorktreesTest's @BeforeEach) can re-pin further for one test without losing what close() restores. Adds an ordered proving test to WorktreeSessionManagerTest asserting the SessionManager logger level is back to a known baseline after the dirty- worktree release test runs; this proves the within-class case only, since JUnit does not guarantee cross-class ordering. Every existing intentional pin (SessionManagerTest's two explicit INFO pins and its @BeforeAll DEBUG baseline) is left untouched, per the ticket. --- .../dev/ltms/fleet/FleetdAwaitHerdrTest.java | 42 +++------ .../fleet/FleetdReplyInboxSelectionTest.java | 74 ++++++--------- .../dev/ltms/fleet/auth/AuditLogTest.java | 22 ++--- .../fleet/inject/CompletionResolverTest.java | 18 +--- .../dev/ltms/fleet/inject/InjectorTest.java | 62 ++----------- .../dev/ltms/fleet/lead/LeadRolloverTest.java | 52 +++-------- .../msg/AmqpConnectionFailureLoggerTest.java | 44 +++------ .../ltms/fleet/session/GitWorktreesTest.java | 46 ++++------ .../fleet/session/SessionManagerTest.java | 53 +---------- .../session/WorktreeSessionManagerTest.java | 84 ++++++++++++++--- .../dev/ltms/fleet/testing/CapturedLog.java | 92 +++++++++++++++++++ 11 files changed, 272 insertions(+), 317 deletions(-) create mode 100644 fleetd/src/test/java/dev/ltms/fleet/testing/CapturedLog.java diff --git a/fleetd/src/test/java/dev/ltms/fleet/FleetdAwaitHerdrTest.java b/fleetd/src/test/java/dev/ltms/fleet/FleetdAwaitHerdrTest.java index 9249c16..391cee4 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/FleetdAwaitHerdrTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/FleetdAwaitHerdrTest.java @@ -1,14 +1,12 @@ package dev.ltms.fleet; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import com.fasterxml.jackson.databind.JsonNode; import dev.ltms.fleet.herdr.HerdrClient; import dev.ltms.fleet.herdr.HerdrException; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.Test; -import org.slf4j.LoggerFactory; import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.LongSupplier; @@ -92,49 +90,42 @@ class FleetdAwaitHerdrTest { @Test void answeredLogsNothingAndSaysReap() { - ListAppender events = attach(); - try { + try (CapturedLog log = attach()) { boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap( new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.ANSWERED, 0L)); assertTrue(shouldReap, "only ANSWERED should tell main to reap orphan workers"); - assertEquals(0, events.list.size(), "the answered path logs nothing itself"); - } finally { - detach(events); + assertEquals(0, log.events().size(), "the answered path logs nothing itself"); } } @Test void deadlinePassedLogsConfiguredAndMeasuredElapsedTogether() { - ListAppender events = attach(); - try { + try (CapturedLog log = attach()) { boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap( new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.DEADLINE_PASSED, 30_500_000_000L)); assertFalse(shouldReap, "a deadline-passed wait must not tell main to reap"); - assertEquals(1, events.list.size()); - ILoggingEvent event = events.list.getFirst(); + assertEquals(1, log.events().size()); + ILoggingEvent event = log.events().getFirst(); assertEquals(Level.WARN, event.getLevel()); assertEquals("herdr did not answer within the configured wait (configured=30s " + "elapsed=30500ms) — starting anyway; /healthz will report degraded until it " + "comes up. Orphaned worker panes (if any) were NOT reaped.", event.getFormattedMessage()); - } finally { - detach(events); } } @Test void interruptedLogsItsOwnMessageAndNeverClaimsTheBudgetElapsed() { - ListAppender events = attach(); - try { + try (CapturedLog log = attach()) { // 3ms: the ticket's own example of "a few milliseconds in", not the 30s budget. boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap( new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.INTERRUPTED, 3_000_000L)); assertFalse(shouldReap, "an interrupted wait must not tell main to reap"); - assertEquals(1, events.list.size()); - ILoggingEvent event = events.list.getFirst(); + assertEquals(1, log.events().size()); + ILoggingEvent event = log.events().getFirst(); assertEquals(Level.WARN, event.getLevel()); String message = event.getFormattedMessage(); assertEquals("herdr wait was interrupted before the configured wait ran out " @@ -143,8 +134,6 @@ class FleetdAwaitHerdrTest { message); assertFalse(message.contains("did not answer"), "an interrupted wait must not be reported as if herdr failed to answer within the budget"); - } finally { - detach(events); } } @@ -197,16 +186,7 @@ class FleetdAwaitHerdrTest { } } - private static ListAppender attach() { - Logger logger = (Logger) LoggerFactory.getLogger(Fleetd.class); - logger.setLevel(Level.DEBUG); - ListAppender appender = new ListAppender<>(); - appender.start(); - logger.addAppender(appender); - return appender; - } - - private static void detach(ListAppender appender) { - ((Logger) LoggerFactory.getLogger(Fleetd.class)).detachAppender(appender); + private static CapturedLog attach() { + return CapturedLog.at(Fleetd.class, Level.DEBUG); } } diff --git a/fleetd/src/test/java/dev/ltms/fleet/FleetdReplyInboxSelectionTest.java b/fleetd/src/test/java/dev/ltms/fleet/FleetdReplyInboxSelectionTest.java index f34adb6..e62f938 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/FleetdReplyInboxSelectionTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/FleetdReplyInboxSelectionTest.java @@ -1,15 +1,13 @@ package dev.ltms.fleet; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import dev.ltms.fleet.config.FleetConfig; import dev.ltms.fleet.msg.AmqpReplyInbox; import dev.ltms.fleet.msg.InMemoryReplyInbox; import dev.ltms.fleet.msg.ReplyInbox; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.Test; -import org.slf4j.LoggerFactory; import java.net.ServerSocket; import java.util.List; @@ -50,43 +48,34 @@ class FleetdReplyInboxSelectionTest { } } - private static ListAppender attach() { - Logger logger = (Logger) LoggerFactory.getLogger(Fleetd.class); + private static CapturedLog attach() { // logback-test.xml pins dev.ltms.fleet to WARN; raise it so INFO selection lines are captured. - logger.setLevel(Level.INFO); - ListAppender appender = new ListAppender<>(); - appender.start(); - logger.addAppender(appender); - return appender; + return CapturedLog.at(Fleetd.class, Level.INFO); } - private static void detach(ListAppender appender) { - ((Logger) LoggerFactory.getLogger(Fleetd.class)).detachAppender(appender); - } - - private static void assertNoLogContains(ListAppender appender, String secret) { - assertTrue(appender.list.stream().noneMatch(e -> e.getFormattedMessage().contains(secret)), + private static void assertNoLogContains(List events, String secret) { + assertTrue(events.stream().noneMatch(e -> e.getFormattedMessage().contains(secret)), "no log line may contain the resolved URI's password"); } @Test void uriEnvSetAndPresentSelectsAmqpWithTheResolvedUri() { FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); - recording(broker, Map.of("LAVINMQ_URI", RESOLVED_URI), false, (opener, appender, inbox) -> { + recording(broker, Map.of("LAVINMQ_URI", RESOLVED_URI), false, (opener, events, inbox) -> { assertEquals(RESOLVED_URI, opener.offeredUri, "the daemon must connect with the value resolved from uriEnv — selection, not just parse"); assertEquals(opener.inbox, inbox, "the AMQP opener's inbox is what is selected"); - assertNoLogContains(appender, SECRET); + assertNoLogContains(events, SECRET); }); } @Test void uriEnvSetButVariableMissingFallsBackToInMemoryAndWarns() { FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); - recording(broker, Map.of(), false, (opener, appender, inbox) -> { + recording(broker, Map.of(), false, (opener, events, inbox) -> { assertInstanceOf(InMemoryReplyInbox.class, inbox); assertNull(opener.offeredUri, "AMQP must never be attempted when the variable is missing"); - assertTrue(hasWarnContaining(appender, "LAVINMQ_URI") && hasWarnContaining(appender, "DISABLED"), + assertTrue(hasWarnContaining(events, "LAVINMQ_URI") && hasWarnContaining(events, "DISABLED"), "a missing uriEnv variable must warn loudly, not fail silently"); }); } @@ -94,10 +83,10 @@ class FleetdReplyInboxSelectionTest { @Test void uriEnvSetButVariableBlankFallsBackToInMemoryAndWarns() { FleetConfig.Broker broker = new FleetConfig.Broker("amqp://user:lame@old:5672/", "LAVINMQ_URI", null); - recording(broker, Map.of("LAVINMQ_URI", " "), false, (opener, appender, inbox) -> { + recording(broker, Map.of("LAVINMQ_URI", " "), false, (opener, events, inbox) -> { assertInstanceOf(InMemoryReplyInbox.class, inbox); assertNull(opener.offeredUri, "a blank env value must not select AMQP, not even via the literal uri"); - assertTrue(hasWarnContaining(appender, "LAVINMQ_URI"), + assertTrue(hasWarnContaining(events, "LAVINMQ_URI"), "a blank uriEnv value must warn, and must not fall back to the literal uri"); }); } @@ -106,22 +95,22 @@ class FleetdReplyInboxSelectionTest { void bothUriAndUriEnvSetUriEnvWinsDeterministically() { FleetConfig.Broker broker = new FleetConfig.Broker("amqp://user:oldpw@old.example:5672/", "LAVINMQ_URI", null); - recording(broker, Map.of("LAVINMQ_URI", RESOLVED_URI), false, (opener, appender, inbox) -> { + recording(broker, Map.of("LAVINMQ_URI", RESOLVED_URI), false, (opener, events, inbox) -> { assertEquals(RESOLVED_URI, opener.offeredUri, "uriEnv must win over uri, deterministically, every run"); - assertTrue(appender.list.stream().anyMatch(e -> e.getFormattedMessage().contains("broker.uri is ignored")), + assertTrue(events.stream().anyMatch(e -> e.getFormattedMessage().contains("broker.uri is ignored")), "must log that the literal uri is ignored when uriEnv is set"); - assertNoLogContains(appender, SECRET); - assertNoLogContains(appender, "oldpw"); + assertNoLogContains(events, SECRET); + assertNoLogContains(events, "oldpw"); }); } @Test void unreachableBrokerStartsDaemonWithInMemoryInboxAndLoudWarning() { FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); - recording(broker, Map.of("LAVINMQ_URI", RESOLVED_URI), true, (opener, appender, inbox) -> { + recording(broker, Map.of("LAVINMQ_URI", RESOLVED_URI), true, (opener, events, inbox) -> { assertInstanceOf(InMemoryReplyInbox.class, inbox, "an unreachable broker must NOT stop the daemon"); - String warn = appender.list.stream() + String warn = events.stream() .filter(e -> e.getLevel() == Level.WARN) .map(ILoggingEvent::getFormattedMessage) .reduce("", (a, b) -> a + "\n" + b) @@ -129,16 +118,16 @@ class FleetdReplyInboxSelectionTest { assertTrue(warn.contains("durable") && warn.contains("soft-state"), "the warning must say exactly what was lost: durable delivery off, replies soft-state"); assertTrue(!warn.contains(SECRET), "the failing URI must be logged with credentials stripped"); - assertNoLogContains(appender, SECRET); + assertNoLogContains(events, SECRET); }); } @Test void noBrokerConfiguredStaysQuietInMemory() { FleetConfig.Broker broker = null; - recording(broker, Map.of(), false, (opener, appender, inbox) -> { + recording(broker, Map.of(), false, (opener, events, inbox) -> { assertInstanceOf(InMemoryReplyInbox.class, inbox); - assertTrue(appender.list.stream().noneMatch(e -> e.getLevel() == Level.WARN), + assertTrue(events.stream().noneMatch(e -> e.getLevel() == Level.WARN), "no broker configured must keep the existing QUIET in-memory path — no warning"); }); } @@ -152,21 +141,18 @@ class FleetdReplyInboxSelectionTest { closedPort = s.getLocalPort(); } FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); - ListAppender appender = attach(); - try { + try (CapturedLog log = attach()) { ReplyInbox inbox = Fleetd.selectReplyInbox( broker, Map.of("LAVINMQ_URI", "amqp://user:" + SECRET + "@127.0.0.1:" + closedPort + "/vh"), AmqpReplyInbox::open); assertInstanceOf(InMemoryReplyInbox.class, inbox, "a genuinely unreachable broker (real AmqpReplyInbox::open) must fall back to in-memory"); - } finally { - detach(appender); + assertNoLogContains(log.events(), SECRET); } - assertNoLogContains(appender, SECRET); } - private boolean hasWarnContaining(ListAppender appender, String fragment) { - return appender.list.stream().anyMatch(e -> + private boolean hasWarnContaining(List events, String fragment) { + return events.stream().anyMatch(e -> e.getLevel() == Level.WARN && e.getFormattedMessage().contains(fragment)); } @@ -174,18 +160,14 @@ class FleetdReplyInboxSelectionTest { private void recording(FleetConfig.Broker broker, Map env, boolean unreachable, Check check) { RecordingAmqp opener = new RecordingAmqp(); opener.unreachable = unreachable; - ListAppender appender = attach(); - ReplyInbox inbox; - try { - inbox = Fleetd.selectReplyInbox(broker, env, opener); - } finally { - detach(appender); + try (CapturedLog log = attach()) { + ReplyInbox inbox = Fleetd.selectReplyInbox(broker, env, opener); + check.run(opener, log.events(), inbox); } - check.run(opener, appender, inbox); } @FunctionalInterface private interface Check { - void run(RecordingAmqp opener, ListAppender appender, ReplyInbox inbox); + void run(RecordingAmqp opener, List events, ReplyInbox inbox); } } diff --git a/fleetd/src/test/java/dev/ltms/fleet/auth/AuditLogTest.java b/fleetd/src/test/java/dev/ltms/fleet/auth/AuditLogTest.java index 338ae45..dd1024c 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/auth/AuditLogTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/auth/AuditLogTest.java @@ -1,15 +1,12 @@ package dev.ltms.fleet.auth; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.LoggerContext; -import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import com.fasterxml.jackson.databind.JsonNode; import com.fasterxml.jackson.databind.ObjectMapper; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; -import org.slf4j.LoggerFactory; import static org.junit.jupiter.api.Assertions.*; @@ -24,28 +21,21 @@ import static org.junit.jupiter.api.Assertions.*; class AuditLogTest { private final ObjectMapper mapper = new ObjectMapper(); - private ListAppender appender; - private ch.qos.logback.classic.Logger auditLogger; + private CapturedLog auditLog; @BeforeEach void attach() { - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - auditLogger = ctx.getLogger("audit"); - appender = new ListAppender<>(); - appender.setContext(ctx); - appender.start(); - auditLogger.addAppender(appender); - auditLogger.setLevel(Level.INFO); + auditLog = CapturedLog.at("audit", Level.INFO); } @AfterEach void detach() { - auditLogger.detachAppender(appender); + auditLog.close(); } private JsonNode onlyRecord() throws Exception { - assertEquals(1, appender.list.size(), "exactly one audit line expected"); - String line = appender.list.getFirst().getFormattedMessage(); + assertEquals(1, auditLog.events().size(), "exactly one audit line expected"); + String line = auditLog.events().getFirst().getFormattedMessage(); return mapper.readTree(line); // throws if the line is not valid JSON } diff --git a/fleetd/src/test/java/dev/ltms/fleet/inject/CompletionResolverTest.java b/fleetd/src/test/java/dev/ltms/fleet/inject/CompletionResolverTest.java index 73e0b01..22dcb6b 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/inject/CompletionResolverTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/inject/CompletionResolverTest.java @@ -1,9 +1,7 @@ package dev.ltms.fleet.inject; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import com.fasterxml.jackson.databind.JsonNode; import com.fasterxml.jackson.databind.ObjectMapper; import dev.ltms.fleet.herdr.AgentControl; @@ -12,8 +10,8 @@ import dev.ltms.fleet.herdr.HerdrClient; import dev.ltms.fleet.msg.Rendezvous; import dev.ltms.fleet.msg.TestTurnTokens; import dev.ltms.fleet.msg.TurnToken; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.Test; -import org.slf4j.LoggerFactory; import java.util.Set; import java.util.regex.Pattern; @@ -470,15 +468,7 @@ class CompletionResolverTest { // CB-564: this used to be a bare DEBUG "failed send to X via turn-stall fallback" — a symptom // with no cause, and below the level anyone watching for member health would see. A fail that // resolves a caller's blocked send is at least WARN and must carry the reason. - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - ch.qos.logback.classic.Logger resolverLog = - (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(CompletionResolver.class); - ListAppender appender = new ListAppender<>(); - appender.setContext(ctx); - appender.start(); - resolverLog.addAppender(appender); - resolverLog.setLevel(Level.WARN); - try { + try (CapturedLog log = CapturedLog.at(CompletionResolver.class, Level.WARN)) { FakeHerdr herdr = new FakeHerdr().readText("stuck on an error screen"); Rendezvous rendezvous = new Rendezvous(); CompletionResolver resolver = new CompletionResolver(new AgentControl(herdr), rendezvous, ExhaustedPatternLookup.none(), ExhaustionSink.none()); @@ -486,7 +476,7 @@ class CompletionResolverTest { resolver.fail("term_a", null); - String warn = appender.list.stream() + String warn = log.events().stream() .filter(e -> e.getLevel().equals(Level.WARN)) .map(ILoggingEvent::getFormattedMessage) .findFirst() @@ -494,8 +484,6 @@ class CompletionResolverTest { assertTrue(warn.contains("term_a"), "the log names the target: " + warn); assertTrue(warn.contains("stuck on an error screen"), "the log carries the reason: " + warn); assertTrue(waiter.isDone()); - } finally { - resolverLog.detachAppender(appender); } } diff --git a/fleetd/src/test/java/dev/ltms/fleet/inject/InjectorTest.java b/fleetd/src/test/java/dev/ltms/fleet/inject/InjectorTest.java index ed18607..ebae95d 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/inject/InjectorTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/inject/InjectorTest.java @@ -1,16 +1,14 @@ package dev.ltms.fleet.inject; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import dev.ltms.fleet.herdr.AgentControl; import dev.ltms.fleet.herdr.AgentStatus; import dev.ltms.fleet.herdr.FakeHerdr; import dev.ltms.fleet.herdr.HerdrException; import dev.ltms.fleet.msg.TestTurnTokens; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.Test; -import org.slf4j.LoggerFactory; import java.util.ArrayList; import java.util.List; @@ -493,23 +491,15 @@ class InjectorTest { void readinessGraceExpiryIsLogged() { // CB-562: the grace-expiry path used to clear the queue silently, so a message that never // reached the worker's pane surfaced elsewhere as an unrelated turn-stall failure. Assert the - // expiry now names the real cause. (ListAppender capture pattern mirrors AuditLogTest.) - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - ch.qos.logback.classic.Logger injectorLog = - (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class); - ListAppender appender = new ListAppender<>(); - appender.setContext(ctx); - appender.start(); - injectorLog.addAppender(appender); - injectorLog.setLevel(Level.WARN); - try { + // expiry now names the real cause. (CapturedLog pattern mirrors AuditLogTest.) + try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> { }); inj.enqueue(T, "task", TestTurnTokens.inert(T)); for (int i = 0; i < READINESS_SAMPLES; i++) inj.onStatus(T, AgentStatus.IDLE); - String warn = appender.list.stream() + String warn = log.events().stream() .filter(e -> e.getLevel().equals(Level.WARN)) .map(ILoggingEvent::getFormattedMessage) .findFirst() @@ -518,8 +508,6 @@ class InjectorTest { assertTrue(warn.contains("never reached"), "the log names the real cause: " + warn); assertTrue(warn.contains("1 queued message"), "the log carries the failed message count: " + warn); - } finally { - injectorLog.detachAppender(appender); } } @@ -533,22 +521,14 @@ class InjectorTest { // count and a labelled configured budget, using literal numbers (240, 60), never // READINESS_GRACE_POLLS or POLL_INTERVAL_MILLIS, so the assertion can't silently track a // constant change instead of catching a real regression. - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - ch.qos.logback.classic.Logger injectorLog = - (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class); - ListAppender appender = new ListAppender<>(); - appender.setContext(ctx); - appender.start(); - injectorLog.addAppender(appender); - injectorLog.setLevel(Level.WARN); - try { + try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> { }); inj.enqueue(T, "task", TestTurnTokens.inert(T)); for (int i = 0; i < READINESS_SAMPLES; i++) inj.onStatus(T, AgentStatus.IDLE); - String warn = appender.list.stream() + String warn = log.events().stream() .filter(e -> e.getLevel().equals(Level.WARN)) .map(ILoggingEvent::getFormattedMessage) .findFirst() @@ -557,8 +537,6 @@ class InjectorTest { "must print the measured poll count as a plain number: " + warn); assertTrue(warn.contains("configured=240 polls/60s"), "must print the configured budget, clearly labelled: " + warn); - } finally { - injectorLog.detachAppender(appender); } } @@ -584,22 +562,14 @@ class InjectorTest { return readings[i]; }; - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - ch.qos.logback.classic.Logger injectorLog = - (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class); - ListAppender appender = new ListAppender<>(); - appender.setContext(ctx); - appender.start(); - injectorLog.addAppender(appender); - injectorLog.setLevel(Level.WARN); - try { + try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> { }, stubClock); inj.enqueue(T, "task", TestTurnTokens.inert(T)); for (int i = 0; i < READINESS_SAMPLES; i++) inj.onStatus(T, AgentStatus.IDLE); - String warn = appender.list.stream() + String warn = log.events().stream() .filter(e -> e.getLevel().equals(Level.WARN)) .map(ILoggingEvent::getFormattedMessage) .findFirst() @@ -609,8 +579,6 @@ class InjectorTest { assertFalse(warn.contains("elapsed=60000ms"), "must not print " + "READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS (240 * 250 = 60000ms) as if it " + "were the measured elapsed time: " + warn); - } finally { - injectorLog.detachAppender(appender); } } @@ -647,21 +615,13 @@ class InjectorTest { // CB-564: a vanished worker used to drop its queue with no log at all — the only trace was // whatever failed downstream (e.g. a caller's send timing out with no clue why). Assert the // drop itself now names the cause and the number of messages it failed. - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - ch.qos.logback.classic.Logger injectorLog = - (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class); - ListAppender appender = new ListAppender<>(); - appender.setContext(ctx); - appender.start(); - injectorLog.addAppender(appender); - injectorLog.setLevel(Level.WARN); - try { + try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> true, _ -> { }); inj.enqueue(T, "orphan", TestTurnTokens.inert(T)); inj.drop(T, new HerdrException("worker gone", "pane_not_found", null)); - String warn = appender.list.stream() + String warn = log.events().stream() .filter(e -> e.getLevel().equals(Level.WARN)) .map(ILoggingEvent::getFormattedMessage) .findFirst() @@ -669,8 +629,6 @@ class InjectorTest { assertTrue(warn.contains(T), "the log names the target terminal: " + warn); assertTrue(warn.contains("1 message"), "the log carries the failed message count: " + warn); assertTrue(warn.contains("worker gone"), "the log carries the real cause: " + warn); - } finally { - injectorLog.detachAppender(appender); } } diff --git a/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java b/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java index cda2c64..5eabaf7 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java @@ -1,23 +1,22 @@ package dev.ltms.fleet.lead; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import com.fasterxml.jackson.databind.JsonNode; import dev.ltms.fleet.config.FleetConfig; import dev.ltms.fleet.herdr.AgentControl; import dev.ltms.fleet.herdr.FakeHerdr; import dev.ltms.fleet.herdr.HerdrClient; import dev.ltms.fleet.herdr.HerdrException; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.DisplayName; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.io.TempDir; -import org.slf4j.LoggerFactory; import java.io.IOException; import java.nio.file.Files; import java.nio.file.Path; +import java.util.List; import java.util.concurrent.atomic.AtomicLong; import java.util.function.Function; import java.util.function.LongSupplier; @@ -862,25 +861,16 @@ class LeadRolloverTest { // ---- fleetd #494: the log lines must print MEASURED values, never the configured budget -- - private static ListAppender attachLog() { - Logger logger = (Logger) LoggerFactory.getLogger(LeadRollover.class); - logger.setLevel(Level.DEBUG); - ListAppender appender = new ListAppender<>(); - appender.start(); - logger.addAppender(appender); - return appender; + private static CapturedLog attachLog() { + return CapturedLog.at(LeadRollover.class, Level.DEBUG); } - private static void detachLog(ListAppender appender) { - ((Logger) LoggerFactory.getLogger(LeadRollover.class)).detachAppender(appender); - } - - private static ILoggingEvent lastEventContaining(ListAppender events, String substring) { - return events.list.stream() + private static ILoggingEvent lastEventContaining(List events, String substring) { + return events.stream() .filter(e -> e.getFormattedMessage().contains(substring)) .reduce((_, b) -> b) .orElseThrow(() -> new AssertionError("no log event contained \"" + substring - + "\"; got: " + events.list.stream().map(ILoggingEvent::getFormattedMessage).toList())); + + "\"; got: " + events.stream().map(ILoggingEvent::getFormattedMessage).toList())); } @Test @@ -914,15 +904,14 @@ class LeadRolloverTest { AtomicLong clock = new AtomicLong(1_000); LeadRollover rollover = newRollover(flipsAfterClear, config, () -> clock.addAndGet(500)); - ListAppender events = attachLog(); - try { + try (CapturedLog log = attachLog()) { LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); assertTrue(decision.accepted(), "every synchronous gate passes; the refusal is logged " + "only, deep inside the deferred continuation"); - ILoggingEvent event = lastEventContaining(events, "NOT sending bootstrapText"); + ILoggingEvent event = lastEventContaining(log.events(), "NOT sending bootstrapText"); assertEquals(Level.WARN, event.getLevel()); String message = event.getFormattedMessage(); assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message); @@ -934,8 +923,6 @@ class LeadRolloverTest { + message); assertFalse(message.contains("within 1s"), "must not present the configured budget as if " + "it were the measured wait duration: " + message); - } finally { - detachLog(events); } } @@ -954,15 +941,14 @@ class LeadRolloverTest { AtomicLong clock = new AtomicLong(1_000); LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500)); - ListAppender events = attachLog(); - try { + try (CapturedLog log = attachLog()) { LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); assertTrue(decision.accepted(), "expected approval; got: " + decision.reason() + " / " + decision.detail()); - ILoggingEvent event = lastEventContaining(events, "releasing rather than wedging the roll"); + ILoggingEvent event = lastEventContaining(log.events(), "releasing rather than wedging the roll"); assertEquals(Level.WARN, event.getLevel(), "the grace-limit release must be WARN, not " + "INFO — it is exactly the case that reported false success in the real incident " + "this fix comes from (a roll that 'succeeded' after 438ms of a 20s budget)"); @@ -982,8 +968,6 @@ class LeadRolloverTest { assertTrue(message.contains("after 8 consecutive IDLE/DONE polls (7 of those were nudged)"), "must print the measured poll count and nudge count as plain numbers, not the " + "PICKUP_GRACE_POLLS constant standing in for either: " + message); - } finally { - detachLog(events); } } @@ -1000,15 +984,14 @@ class LeadRolloverTest { AtomicLong clock = new AtomicLong(1_000); LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500)); - ListAppender events = attachLog(); - try { + try (CapturedLog log = attachLog()) { LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); assertTrue(decision.accepted(), "expected approval; got: " + decision.reason() + " / " + decision.detail()); - ILoggingEvent event = lastEventContaining(events, "lead-rollover: rolled"); + ILoggingEvent event = lastEventContaining(log.events(), "lead-rollover: rolled"); assertEquals(Level.INFO, event.getLevel()); String message = event.getFormattedMessage(); // fleetd #494 follow-up: waitUntilAtTurnBoundary now also reads the injected clock one @@ -1018,8 +1001,6 @@ class LeadRolloverTest { assertTrue(message.contains("elapsedMs=7000"), "must print the MEASURED elapsed time for " + "the whole roll — with this fixture's advancing clock, the full roll (turn-settle " + "wait + /clear wait + bootstrapText) took 7000ms: " + message); - } finally { - detachLog(events); } } @@ -1040,8 +1021,7 @@ class LeadRolloverTest { AtomicLong clock = new AtomicLong(1_000); LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500)); - ListAppender events = attachLog(); - try { + try (CapturedLog log = attachLog()) { LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); @@ -1049,7 +1029,7 @@ class LeadRolloverTest { + "only inside the deferred continuation, which this test's synchronous runner " + "has already run to completion by the time confirm() returns"); - ILoggingEvent event = lastEventContaining(events, "refusing to send /clear at all"); + ILoggingEvent event = lastEventContaining(log.events(), "refusing to send /clear at all"); assertEquals(Level.WARN, event.getLevel()); String message = event.getFormattedMessage(); assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message); @@ -1058,8 +1038,6 @@ class LeadRolloverTest { + "1s(=1000ms) configured budget: " + message); assertFalse(message.contains("within 1s"), "must not present the configured budget as if " + "it were the measured wait duration: " + message); - } finally { - detachLog(events); } } } diff --git a/fleetd/src/test/java/dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java b/fleetd/src/test/java/dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java index e6d59e9..e3086fe 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java @@ -1,17 +1,17 @@ package dev.ltms.fleet.msg; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import com.rabbitmq.client.Channel; import com.rabbitmq.client.ConnectionFactory; import com.rabbitmq.client.impl.DefaultExceptionHandler; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.Test; import org.slf4j.LoggerFactory; import java.io.IOException; import java.lang.reflect.Proxy; +import java.util.List; import java.util.concurrent.atomic.AtomicInteger; import static org.junit.jupiter.api.Assertions.assertEquals; @@ -32,21 +32,17 @@ class AmqpConnectionFailureLoggerTest { assertEquals(AmqpConnectionFailureLogger.REPLY_INBOX, inboxHandler.connectionName()); assertEquals(AmqpConnectionFailureLogger.LEAD_MAILBOX, mailboxHandler.connectionName()); - ListAppender inboxEvents = attach(AmqpReplyInbox.class); - ListAppender mailboxEvents = attach(LeadMailbox.class); IllegalStateException inboxFailure = new IllegalStateException("inbox failure"); IllegalStateException mailboxFailure = new IllegalStateException("mailbox failure"); - try { + try (CapturedLog inboxLog = attach(AmqpReplyInbox.class); + CapturedLog mailboxLog = attach(LeadMailbox.class)) { inboxHandler.handleUnexpectedConnectionDriverException(null, inboxFailure); mailboxHandler.handleConnectionRecoveryException(null, mailboxFailure); - assertError(inboxEvents, "AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred", + assertError(inboxLog.events(), "AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred", inboxFailure, "inbox failure line"); - assertError(mailboxEvents, "AMQP connection fleetd-lead-mailbox: Caught an exception during connection recovery!", + assertError(mailboxLog.events(), "AMQP connection fleetd-lead-mailbox: Caught an exception during connection recovery!", mailboxFailure, "mailbox recovery line"); - } finally { - detach(AmqpReplyInbox.class, inboxEvents); - detach(LeadMailbox.class, mailboxEvents); } } @@ -54,17 +50,14 @@ class AmqpConnectionFailureLoggerTest { void connectionResetKeepsForgivingHandlerWarningSemantics() { AmqpConnectionFailureLogger handler = new AmqpConnectionFailureLogger( AmqpConnectionFailureLogger.REPLY_INBOX, LoggerFactory.getLogger(AmqpReplyInbox.class)); - ListAppender events = attach(AmqpReplyInbox.class); - try { + try (CapturedLog log = attach(AmqpReplyInbox.class)) { handler.handleUnexpectedConnectionDriverException(null, new IOException("Connection reset")); - assertEquals(1, events.list.size(), "the handler must still log a reset"); - ILoggingEvent event = events.list.getFirst(); + assertEquals(1, log.events().size(), "the handler must still log a reset"); + ILoggingEvent event = log.events().getFirst(); assertEquals(Level.WARN, event.getLevel(), "ForgivingExceptionHandler logs connection resets at WARN"); assertEquals("AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred " + "(Exception message: Connection reset)", event.getFormattedMessage()); assertTrue(event.getThrowableProxy() == null, "ForgivingExceptionHandler does not attach a reset stack trace"); - } finally { - detach(AmqpReplyInbox.class, events); } } @@ -103,17 +96,8 @@ class AmqpConnectionFailureLoggerTest { "all exception-handling methods must remain inherited from DefaultExceptionHandler"); } - private static ListAppender attach(Class owner) { - Logger logger = (Logger) LoggerFactory.getLogger(owner); - logger.setLevel(Level.DEBUG); - ListAppender appender = new ListAppender<>(); - appender.start(); - logger.addAppender(appender); - return appender; - } - - private static void detach(Class owner, ListAppender appender) { - ((Logger) LoggerFactory.getLogger(owner)).detachAppender(appender); + private static CapturedLog attach(Class owner) { + return CapturedLog.at(owner, Level.DEBUG); } private static AmqpConnectionFailureLogger installedStrictHandler(ConnectionFactory factory, String connection) { @@ -123,9 +107,9 @@ class AmqpConnectionFailureLoggerTest { return assertInstanceOf(AmqpConnectionFailureLogger.class, factory.getExceptionHandler()); } - private static void assertError(ListAppender events, String message, Throwable cause, String name) { - assertEquals(1, events.list.size(), name); - ILoggingEvent event = events.list.getFirst(); + private static void assertError(List events, String message, Throwable cause, String name) { + assertEquals(1, events.size(), name); + ILoggingEvent event = events.getFirst(); assertEquals(Level.ERROR, event.getLevel(), name); assertEquals(message, event.getFormattedMessage(), name); assertEquals(cause.toString(), event.getThrowableProxy().getClassName() + ": " diff --git a/fleetd/src/test/java/dev/ltms/fleet/session/GitWorktreesTest.java b/fleetd/src/test/java/dev/ltms/fleet/session/GitWorktreesTest.java index c36a8e7..ea12690 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/session/GitWorktreesTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/session/GitWorktreesTest.java @@ -1,16 +1,13 @@ package dev.ltms.fleet.session; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.Logger; -import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.spi.IThrowableProxy; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; +import dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.io.TempDir; -import org.slf4j.LoggerFactory; import java.io.IOException; import java.nio.charset.StandardCharsets; @@ -489,36 +486,33 @@ class GitWorktreesTest { // ---- CB-189: broader remote-URL coverage — every remote, both fetch and push URLs, any // non-SSH scheme. Reporting only, additive to the origin/https strip-and-refuse tests above. ---- - private Logger reportingLogger; - private ListAppender reportingAppender; + private CapturedLog reportingLog; /** {@link GitWorktrees}'s own logger, captured fresh for each test so assertions never see a - * message left over from a previous test. */ + * message left over from a previous test. fleetd #529: {@link CapturedLog#close} restores the + * level it captured here (whatever it truly was before this test, not just WARN), so a test + * below that further lowers the level to INFO for its own assertion (via {@link + * #reportingLog}'s {@link CapturedLog#setLevel}) can never leak that INFO pin past its own + * {@code @AfterEach} — every test's window is self-contained. */ @BeforeEach void attachReportingLogCapture() { - LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); - reportingLogger = ctx.getLogger(GitWorktrees.class); - reportingLogger.setLevel(Level.WARN); - reportingAppender = new ListAppender<>(); - reportingAppender.setContext(ctx); - reportingAppender.start(); - reportingLogger.addAppender(reportingAppender); + reportingLog = CapturedLog.at(GitWorktrees.class, Level.WARN); } @AfterEach void detachReportingLogCapture() { - reportingLogger.detachAppender(reportingAppender); + reportingLog.close(); } private List capturedMessages() { - return reportingAppender.list.stream().map(ILoggingEvent::getFormattedMessage).toList(); + return reportingLog.events().stream().map(ILoggingEvent::getFormattedMessage).toList(); } /** Asserts {@code secret} appears in no captured message, and in no attached exception's * message either — the constraint is that a credential must never reach a log, however it * would have gotten there. */ private void assertNoLeak(String secret) { - for (ILoggingEvent event : reportingAppender.list) { + for (ILoggingEvent event : reportingLog.events()) { assertFalse(event.getFormattedMessage().contains(secret), "log message leaked a credential (" + secret + "): " + event.getFormattedMessage()); IThrowableProxy thrown = event.getThrowableProxy(); @@ -596,7 +590,7 @@ class GitWorktreesTest { new GitWorktrees(tmp.resolve("wts").toString()).add(repo.toString(), "cb-189-d", "HEAD"); - assertTrue(reportingAppender.list.isEmpty(), + assertTrue(reportingLog.events().isEmpty(), "expected no report for an ssh remote and a credential-free https remote, got:\n" + capturedMessages()); } @@ -812,7 +806,7 @@ class GitWorktreesTest { /** Criterion 1, all three present: the summary names the denominator and every neutralized file. */ @Test void isolateToolSurfaceLogsAllThreeConfigsNeutralized(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = initRepoWithAllThreeConfigs(tmp.resolve("repo")); new GitWorktrees(tmp.resolve("wts").toString()).add(repo.toString(), "cb-134-log-all", "HEAD"); @@ -827,7 +821,7 @@ class GitWorktreesTest { /** Criterion 1, two absent: the summary must still name the denominator and say why. */ @Test void isolateToolSurfaceLogsAbsentConfigsWithReason(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = initRepo(tmp.resolve("repo")); // only .mcp.json + README committed new GitWorktrees(tmp.resolve("wts").toString()).add(repo.toString(), "cb-134-log-partial", "HEAD"); @@ -1435,7 +1429,7 @@ class GitWorktreesTest { /** Criterion 2: both candidates present — the summary line names both and the denominator. */ @Test void overlayParityLogsBothCopiedWhenBothCandidatesArePresent(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = initRepo(tmp.resolve("repo")); Files.writeString(repo.resolve(".env"), "A=1\n"); Files.writeString(repo.resolve(".envrc"), "export A=1\n"); @@ -1452,7 +1446,7 @@ class GitWorktreesTest { * denominator, and why the other candidate was not copied. */ @Test void overlayParityLogsOneCopiedOneAbsent(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = initRepo(tmp.resolve("repo")); Files.writeString(repo.resolve(".env"), "A=1\n"); // .envrc deliberately not created — the absent candidate. @@ -1472,7 +1466,7 @@ class GitWorktreesTest { * change, silently, unless this line told it so beforehand. */ @Test void overlayParityLogsSkipWorktreeConsequenceForATrackedFile(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = initRepo(tmp.resolve("repo")); Files.writeString(repo.resolve(".env"), "A=1\n"); git(repo, "add", ".env"); @@ -1495,7 +1489,7 @@ class GitWorktreesTest { /** Criterion 5: null and empty overlay lists return quietly — no exception, no log noise. */ @Test void overlayParityWithNoCandidatesLogsNothing(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = initRepo(tmp.resolve("repo")); Path wt = bareWorktree(repo, tmp.resolve("wt"), "cb134-empty"); GitWorktrees worktrees = new GitWorktrees(tmp.resolve("wts").toString()); @@ -1503,7 +1497,7 @@ class GitWorktreesTest { worktrees.overlayParity(repo.toString(), wt.toString(), null); worktrees.overlayParity(repo.toString(), wt.toString(), List.of()); - assertTrue(reportingAppender.list.isEmpty(), + assertTrue(reportingLog.events().isEmpty(), "a null/empty overlay must log nothing, got:\n" + capturedMessages()); } @@ -1683,7 +1677,7 @@ class GitWorktreesTest { * denominator, what was seeded, and what was kept because the repo already had it. */ @Test void seedSkillsLogsSeededAndKept(@TempDir Path tmp) throws Exception { - reportingLogger.setLevel(Level.INFO); + reportingLog.setLevel(Level.INFO); Path repo = tmp.resolve("repo"); Files.createDirectories(repo); git(repo, "init", "-q", "-b", "main"); 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 3e70705..886f1ff 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java @@ -1,9 +1,7 @@ package dev.ltms.fleet.session; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import dev.ltms.fleet.auth.MemberRegistry; import dev.ltms.fleet.auth.MemberLifecycle; import dev.ltms.fleet.config.ConfigRef; @@ -25,6 +23,7 @@ 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 dev.ltms.fleet.testing.CapturedLog; import org.junit.jupiter.api.AfterAll; import org.junit.jupiter.api.BeforeAll; import org.junit.jupiter.api.MethodOrderer; @@ -123,54 +122,8 @@ 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); - } - } + // fleetd #529: CapturedLog moved to dev.ltms.fleet.testing.CapturedLog (imported above) so + // every test file shares one implementation instead of each hand-rolling its own capture. /** * CB-581: a {@link Worktrees} test double whose {@code hasUncommitted} and {@code remove} can diff --git a/fleetd/src/test/java/dev/ltms/fleet/session/WorktreeSessionManagerTest.java b/fleetd/src/test/java/dev/ltms/fleet/session/WorktreeSessionManagerTest.java index 284c588..336275b 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/session/WorktreeSessionManagerTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/session/WorktreeSessionManagerTest.java @@ -7,13 +7,17 @@ import dev.ltms.fleet.herdr.AgentControl; import dev.ltms.fleet.herdr.FakeHerdr; import dev.ltms.fleet.herdr.WorkspaceControl; import ch.qos.logback.classic.Level; -import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.spi.ILoggingEvent; -import ch.qos.logback.core.read.ListAppender; import dev.ltms.fleet.member.ClaudeCodeLauncher; import dev.ltms.fleet.msg.TestTurnTokens; import dev.ltms.fleet.peer.MemberRole; +import dev.ltms.fleet.testing.CapturedLog; +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.slf4j.LoggerFactory; import java.util.List; @@ -27,9 +31,41 @@ import static org.junit.jupiter.api.Assertions.*; * CB-301-ext acceptance tests for worktree provisioning and config-parity overlay. * No live git — every Worktrees call is handled by {@link FakeWorktrees} and every herdr * call by {@link FakeHerdr}, matching the project's fake-based test style. + * + *

fleetd #529: only {@link #releasePreservesDirtyWorktreeAndLogsWarn} (explicitly + * {@link Order#value() @Order(1)}) and the proving test right after it + * ({@link #sharedSessionManagerLoggerLevelIsRestoredAfterDirtyWorktreeReleasePinsWarn}, + * {@code @Order(2)}) care about method order — every other test here has no {@code @Order} and so + * runs after both (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 WorktreeSessionManagerTest { + /** + * fleetd #529: the level {@link SessionManager}'s logger had when this class started, captured + * before any test here touches it, then forced to a distinctive, known value (TRACE) so {@link + * #sharedSessionManagerLoggerLevelIsRestoredAfterDirtyWorktreeReleasePinsWarn} can tell "the + * level came back to what it was" apart from "the level happens to already be WARN because + * some other test class in this JVM fork (surefire reuses forks by default) left it there". + */ + private static ch.qos.logback.classic.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(ch.qos.logback.classic.Level.TRACE); + } + + @AfterAll + static void restoreSessionManagerLoggerLevel() { + ch.qos.logback.classic.Logger sessionLog = + (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class); + sessionLog.setLevel(sessionManagerLevelBeforeThisClass); + } + private static MemberRegistry members() { return new MemberRegistry(new FleetConfig.Fleet(Map.of(), Map.of("architect", new FleetConfig.Slot("ltms-local")), @@ -254,6 +290,7 @@ class WorktreeSessionManagerTest { * path, the session, and the cause an operator needs to find the work. */ @Test + @Order(1) void releasePreservesDirtyWorktreeAndLogsWarn() { FakeHerdr herdr = new FakeHerdr(); FakeWorktrees worktrees = new FakeWorktrees().withRepoRoot("/repo").withPrefix("/wt") @@ -262,21 +299,13 @@ class WorktreeSessionManagerTest { MemberSession s = sessions.acquire("ltms-local", null, "/caller/proj", null, new WorktreeRequest("cb-576", null)); - 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)) { sessions.release(s.paneId()); assertTrue(herdr.called("pane.close"), "release still tears the worker pane down"); assertTrue(worktrees.removeCalls().isEmpty(), "a dirty worktree is never removed — it holds the only copy of the work"); - String warn = appender.list.stream() + String warn = log.events().stream() .filter(e -> e.getLevel().equals(Level.WARN)) .map(ILoggingEvent::getFormattedMessage) .filter(m -> m.contains("dirty worktree")) @@ -285,11 +314,38 @@ class WorktreeSessionManagerTest { assertTrue(warn.contains(s.worktree()), "the WARN names the worktree path: " + warn); assertTrue(warn.contains(s.terminalId()), "the WARN names the session: " + warn); assertTrue(warn.contains("COMPLETED"), "the WARN names the release cause: " + warn); - } finally { - sessionLog.detachAppender(appender); } } + /** + * fleetd #529 proving test: pins that the leak this ticket fixes stays fixed. {@link + * #releasePreservesDirtyWorktreeAndLogsWarn} above (which runs immediately before this, via + * {@code @Order}) pins the shared {@link SessionManager} logger to WARN through a {@link + * CapturedLog}; if {@link CapturedLog#close} only detached the appender — the original bug — + * the level would still read WARN here instead of the {@code TRACE} 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. + * + *

This proves only the WITHIN-CLASS case: JUnit 5's {@code @TestMethodOrder} orders methods + * inside one class, not test classes relative to each other, and surefire's default class order + * is not something a single test can force. The cross-class leak fleetd #525 measured — this + * class's {@code releasePreservesDirtyWorktreeAndLogsWarn} pinning WARN and bleeding into a + * later-running {@code SessionManagerTest} in the same fork — is fixed by the same {@link + * CapturedLog} mechanism proven here, but that cross-class ordering itself is NOT asserted by + * any test and remains unproven by construction. + */ + @Test + @Order(2) + void sharedSessionManagerLoggerLevelIsRestoredAfterDirtyWorktreeReleasePinsWarn() { + ch.qos.logback.classic.Logger sessionLog = + (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class); + assertEquals(ch.qos.logback.classic.Level.TRACE, sessionLog.getLevel(), + "releasePreservesDirtyWorktreeAndLogsWarn pins the shared SessionManager logger to " + + "WARN; its cleanup must restore the level it captured (TRACE, set by this " + + "class's @BeforeAll) rather than leaving WARN pinned for every test that " + + "runs after it"); + } + /** * CB-576 review (fleetd #116). A worktree that is already gone (operator cleanup, * {@code git worktree prune}, an earlier half-completed release) must not break teardown. diff --git a/fleetd/src/test/java/dev/ltms/fleet/testing/CapturedLog.java b/fleetd/src/test/java/dev/ltms/fleet/testing/CapturedLog.java new file mode 100644 index 0000000..9980b73 --- /dev/null +++ b/fleetd/src/test/java/dev/ltms/fleet/testing/CapturedLog.java @@ -0,0 +1,92 @@ +package dev.ltms.fleet.testing; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import org.slf4j.LoggerFactory; + +import java.util.List; + +/** + * fleetd #529 (promoted from {@code SessionManagerTest}, merged in #527 for fleetd #525): captures + * a logger's output and, on {@link #close}, restores both the appender and the level to + * what they were before. + * + *

{@code ch.qos.logback.classic.Logger} instances are cached per class and shared across the + * whole JVM — and surefire reuses forks by default — so a bare {@code addAppender}/{@code + * setLevel} pair whose {@code finally} only detaches the appender leaves the level pinned for + * every test that runs after it, in the same class or in a completely unrelated one sharing the + * fork. try-with-resources makes "restored the appender but not the level" impossible to write, + * because there is only one thing to close. + * + *

This is the one way to pin or capture a logger's level and output in this test tree — do not + * hand-roll the {@code ListAppender} + {@code setLevel} + {@code finally detachAppender} pattern; + * use {@link #at} or {@link #of} instead. + */ +public final class CapturedLog implements AutoCloseable { + private final Logger logger; + private final Level originalLevel; + private final ListAppender appender; + + private CapturedLog(Logger logger, Level pinnedLevel) { + LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); + this.logger = logger; + 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. */ + public static CapturedLog at(Class loggerClass, Level pinnedLevel) { + return new CapturedLog((Logger) LoggerFactory.getLogger(loggerClass), pinnedLevel); + } + + /** Capture {@code loggerClass}'s output without changing its level. */ + public static CapturedLog of(Class loggerClass) { + return new CapturedLog((Logger) LoggerFactory.getLogger(loggerClass), null); + } + + /** + * Capture the named logger's output, pinning its level to {@code pinnedLevel}. For a logger + * obtained in production code via {@code LoggerFactory.getLogger("some-name")} rather than a + * class — e.g. {@code AuditLog}'s {@code "audit"} logger — where {@link #at(Class, Level)} + * would capture the wrong {@code Logger} instance (class name and logger name are different + * strings and resolve to different cached loggers). + */ + public static CapturedLog at(String loggerName, Level pinnedLevel) { + return new CapturedLog((Logger) LoggerFactory.getLogger(loggerName), pinnedLevel); + } + + /** Capture the named logger's output without changing its level. See {@link #at(String, Level)}. */ + public static CapturedLog of(String loggerName) { + return new CapturedLog((Logger) LoggerFactory.getLogger(loggerName), null); + } + + public List events() { + return appender.list; + } + + /** + * Re-pin the level while this capture is still open — for example to lower it further for one + * assertion inside a test whose fixture already pinned a coarser baseline in {@code @BeforeEach}. + * This does not change what {@link #close} restores: that is always the level captured when + * this instance was created, never a value set through this method. + */ + public void setLevel(Level level) { + logger.setLevel(level); + } + + @Override + public void close() { + logger.detachAppender(appender); + logger.setLevel(originalLevel); + } +}