fleetd #529: promote CapturedLog to a shared test helper, close the logger-level leak
CI / contract (pull_request) Successful in 1m14s
CI / build (pull_request) Successful in 1m39s

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.
This commit is contained in:
Dai Ha
2026-09-12 12:48:49 +07:00
parent a6415f3e52
commit 8ea5c2bb1f
11 changed files with 272 additions and 317 deletions
@@ -1,14 +1,12 @@
package dev.ltms.fleet; package dev.ltms.fleet;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent; 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.JsonNode;
import dev.ltms.fleet.herdr.HerdrClient; import dev.ltms.fleet.herdr.HerdrClient;
import dev.ltms.fleet.herdr.HerdrException; import dev.ltms.fleet.herdr.HerdrException;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicBoolean;
import java.util.function.LongSupplier; import java.util.function.LongSupplier;
@@ -92,49 +90,42 @@ class FleetdAwaitHerdrTest {
@Test @Test
void answeredLogsNothingAndSaysReap() { void answeredLogsNothingAndSaysReap() {
ListAppender<ILoggingEvent> events = attach(); try (CapturedLog log = attach()) {
try {
boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap( boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap(
new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.ANSWERED, 0L)); new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.ANSWERED, 0L));
assertTrue(shouldReap, "only ANSWERED should tell main to reap orphan workers"); assertTrue(shouldReap, "only ANSWERED should tell main to reap orphan workers");
assertEquals(0, events.list.size(), "the answered path logs nothing itself"); assertEquals(0, log.events().size(), "the answered path logs nothing itself");
} finally {
detach(events);
} }
} }
@Test @Test
void deadlinePassedLogsConfiguredAndMeasuredElapsedTogether() { void deadlinePassedLogsConfiguredAndMeasuredElapsedTogether() {
ListAppender<ILoggingEvent> events = attach(); try (CapturedLog log = attach()) {
try {
boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap( boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap(
new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.DEADLINE_PASSED, 30_500_000_000L)); new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.DEADLINE_PASSED, 30_500_000_000L));
assertFalse(shouldReap, "a deadline-passed wait must not tell main to reap"); assertFalse(shouldReap, "a deadline-passed wait must not tell main to reap");
assertEquals(1, events.list.size()); assertEquals(1, log.events().size());
ILoggingEvent event = events.list.getFirst(); ILoggingEvent event = log.events().getFirst();
assertEquals(Level.WARN, event.getLevel()); assertEquals(Level.WARN, event.getLevel());
assertEquals("herdr did not answer within the configured wait (configured=30s " assertEquals("herdr did not answer within the configured wait (configured=30s "
+ "elapsed=30500ms) — starting anyway; /healthz will report degraded until it " + "elapsed=30500ms) — starting anyway; /healthz will report degraded until it "
+ "comes up. Orphaned worker panes (if any) were NOT reaped.", + "comes up. Orphaned worker panes (if any) were NOT reaped.",
event.getFormattedMessage()); event.getFormattedMessage());
} finally {
detach(events);
} }
} }
@Test @Test
void interruptedLogsItsOwnMessageAndNeverClaimsTheBudgetElapsed() { void interruptedLogsItsOwnMessageAndNeverClaimsTheBudgetElapsed() {
ListAppender<ILoggingEvent> events = attach(); try (CapturedLog log = attach()) {
try {
// 3ms: the ticket's own example of "a few milliseconds in", not the 30s budget. // 3ms: the ticket's own example of "a few milliseconds in", not the 30s budget.
boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap( boolean shouldReap = Fleetd.logHerdrWaitOutcomeAndShouldReap(
new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.INTERRUPTED, 3_000_000L)); new Fleetd.HerdrAwaitOutcome(Fleetd.HerdrWaitResult.INTERRUPTED, 3_000_000L));
assertFalse(shouldReap, "an interrupted wait must not tell main to reap"); assertFalse(shouldReap, "an interrupted wait must not tell main to reap");
assertEquals(1, events.list.size()); assertEquals(1, log.events().size());
ILoggingEvent event = events.list.getFirst(); ILoggingEvent event = log.events().getFirst();
assertEquals(Level.WARN, event.getLevel()); assertEquals(Level.WARN, event.getLevel());
String message = event.getFormattedMessage(); String message = event.getFormattedMessage();
assertEquals("herdr wait was interrupted before the configured wait ran out " assertEquals("herdr wait was interrupted before the configured wait ran out "
@@ -143,8 +134,6 @@ class FleetdAwaitHerdrTest {
message); message);
assertFalse(message.contains("did not answer"), assertFalse(message.contains("did not answer"),
"an interrupted wait must not be reported as if herdr failed to answer within the budget"); "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<ILoggingEvent> attach() { private static CapturedLog attach() {
Logger logger = (Logger) LoggerFactory.getLogger(Fleetd.class); return CapturedLog.at(Fleetd.class, Level.DEBUG);
logger.setLevel(Level.DEBUG);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.start();
logger.addAppender(appender);
return appender;
}
private static void detach(ListAppender<ILoggingEvent> appender) {
((Logger) LoggerFactory.getLogger(Fleetd.class)).detachAppender(appender);
} }
} }
@@ -1,15 +1,13 @@
package dev.ltms.fleet; package dev.ltms.fleet;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import dev.ltms.fleet.config.FleetConfig; import dev.ltms.fleet.config.FleetConfig;
import dev.ltms.fleet.msg.AmqpReplyInbox; import dev.ltms.fleet.msg.AmqpReplyInbox;
import dev.ltms.fleet.msg.InMemoryReplyInbox; import dev.ltms.fleet.msg.InMemoryReplyInbox;
import dev.ltms.fleet.msg.ReplyInbox; import dev.ltms.fleet.msg.ReplyInbox;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import java.net.ServerSocket; import java.net.ServerSocket;
import java.util.List; import java.util.List;
@@ -50,43 +48,34 @@ class FleetdReplyInboxSelectionTest {
} }
} }
private static ListAppender<ILoggingEvent> attach() { private static CapturedLog attach() {
Logger logger = (Logger) LoggerFactory.getLogger(Fleetd.class);
// logback-test.xml pins dev.ltms.fleet to WARN; raise it so INFO selection lines are captured. // logback-test.xml pins dev.ltms.fleet to WARN; raise it so INFO selection lines are captured.
logger.setLevel(Level.INFO); return CapturedLog.at(Fleetd.class, Level.INFO);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.start();
logger.addAppender(appender);
return appender;
} }
private static void detach(ListAppender<ILoggingEvent> appender) { private static void assertNoLogContains(List<ILoggingEvent> events, String secret) {
((Logger) LoggerFactory.getLogger(Fleetd.class)).detachAppender(appender); assertTrue(events.stream().noneMatch(e -> e.getFormattedMessage().contains(secret)),
}
private static void assertNoLogContains(ListAppender<ILoggingEvent> appender, String secret) {
assertTrue(appender.list.stream().noneMatch(e -> e.getFormattedMessage().contains(secret)),
"no log line may contain the resolved URI's password"); "no log line may contain the resolved URI's password");
} }
@Test @Test
void uriEnvSetAndPresentSelectsAmqpWithTheResolvedUri() { void uriEnvSetAndPresentSelectsAmqpWithTheResolvedUri() {
FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); 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, assertEquals(RESOLVED_URI, opener.offeredUri,
"the daemon must connect with the value resolved from uriEnv — selection, not just parse"); "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"); assertEquals(opener.inbox, inbox, "the AMQP opener's inbox is what is selected");
assertNoLogContains(appender, SECRET); assertNoLogContains(events, SECRET);
}); });
} }
@Test @Test
void uriEnvSetButVariableMissingFallsBackToInMemoryAndWarns() { void uriEnvSetButVariableMissingFallsBackToInMemoryAndWarns() {
FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); 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); assertInstanceOf(InMemoryReplyInbox.class, inbox);
assertNull(opener.offeredUri, "AMQP must never be attempted when the variable is missing"); 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"); "a missing uriEnv variable must warn loudly, not fail silently");
}); });
} }
@@ -94,10 +83,10 @@ class FleetdReplyInboxSelectionTest {
@Test @Test
void uriEnvSetButVariableBlankFallsBackToInMemoryAndWarns() { void uriEnvSetButVariableBlankFallsBackToInMemoryAndWarns() {
FleetConfig.Broker broker = new FleetConfig.Broker("amqp://user:lame@old:5672/", "LAVINMQ_URI", null); 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); assertInstanceOf(InMemoryReplyInbox.class, inbox);
assertNull(opener.offeredUri, "a blank env value must not select AMQP, not even via the literal uri"); 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"); "a blank uriEnv value must warn, and must not fall back to the literal uri");
}); });
} }
@@ -106,22 +95,22 @@ class FleetdReplyInboxSelectionTest {
void bothUriAndUriEnvSetUriEnvWinsDeterministically() { void bothUriAndUriEnvSetUriEnvWinsDeterministically() {
FleetConfig.Broker broker FleetConfig.Broker broker
= new FleetConfig.Broker("amqp://user:oldpw@old.example:5672/", "LAVINMQ_URI", null); = 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, assertEquals(RESOLVED_URI, opener.offeredUri,
"uriEnv must win over uri, deterministically, every run"); "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"); "must log that the literal uri is ignored when uriEnv is set");
assertNoLogContains(appender, SECRET); assertNoLogContains(events, SECRET);
assertNoLogContains(appender, "oldpw"); assertNoLogContains(events, "oldpw");
}); });
} }
@Test @Test
void unreachableBrokerStartsDaemonWithInMemoryInboxAndLoudWarning() { void unreachableBrokerStartsDaemonWithInMemoryInboxAndLoudWarning() {
FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); 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"); 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) .filter(e -> e.getLevel() == Level.WARN)
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.reduce("", (a, b) -> a + "\n" + b) .reduce("", (a, b) -> a + "\n" + b)
@@ -129,16 +118,16 @@ class FleetdReplyInboxSelectionTest {
assertTrue(warn.contains("durable") && warn.contains("soft-state"), assertTrue(warn.contains("durable") && warn.contains("soft-state"),
"the warning must say exactly what was lost: durable delivery off, replies 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"); assertTrue(!warn.contains(SECRET), "the failing URI must be logged with credentials stripped");
assertNoLogContains(appender, SECRET); assertNoLogContains(events, SECRET);
}); });
} }
@Test @Test
void noBrokerConfiguredStaysQuietInMemory() { void noBrokerConfiguredStaysQuietInMemory() {
FleetConfig.Broker broker = null; FleetConfig.Broker broker = null;
recording(broker, Map.of(), false, (opener, appender, inbox) -> { recording(broker, Map.of(), false, (opener, events, inbox) -> {
assertInstanceOf(InMemoryReplyInbox.class, 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"); "no broker configured must keep the existing QUIET in-memory path — no warning");
}); });
} }
@@ -152,21 +141,18 @@ class FleetdReplyInboxSelectionTest {
closedPort = s.getLocalPort(); closedPort = s.getLocalPort();
} }
FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null); FleetConfig.Broker broker = new FleetConfig.Broker(null, "LAVINMQ_URI", null);
ListAppender<ILoggingEvent> appender = attach(); try (CapturedLog log = attach()) {
try {
ReplyInbox inbox = Fleetd.selectReplyInbox( ReplyInbox inbox = Fleetd.selectReplyInbox(
broker, Map.of("LAVINMQ_URI", "amqp://user:" + SECRET + "@127.0.0.1:" + closedPort + "/vh"), broker, Map.of("LAVINMQ_URI", "amqp://user:" + SECRET + "@127.0.0.1:" + closedPort + "/vh"),
AmqpReplyInbox::open); AmqpReplyInbox::open);
assertInstanceOf(InMemoryReplyInbox.class, inbox, assertInstanceOf(InMemoryReplyInbox.class, inbox,
"a genuinely unreachable broker (real AmqpReplyInbox::open) must fall back to in-memory"); "a genuinely unreachable broker (real AmqpReplyInbox::open) must fall back to in-memory");
} finally { assertNoLogContains(log.events(), SECRET);
detach(appender);
} }
assertNoLogContains(appender, SECRET);
} }
private boolean hasWarnContaining(ListAppender<ILoggingEvent> appender, String fragment) { private boolean hasWarnContaining(List<ILoggingEvent> events, String fragment) {
return appender.list.stream().anyMatch(e -> return events.stream().anyMatch(e ->
e.getLevel() == Level.WARN && e.getFormattedMessage().contains(fragment)); e.getLevel() == Level.WARN && e.getFormattedMessage().contains(fragment));
} }
@@ -174,18 +160,14 @@ class FleetdReplyInboxSelectionTest {
private void recording(FleetConfig.Broker broker, Map<String, String> env, boolean unreachable, Check check) { private void recording(FleetConfig.Broker broker, Map<String, String> env, boolean unreachable, Check check) {
RecordingAmqp opener = new RecordingAmqp(); RecordingAmqp opener = new RecordingAmqp();
opener.unreachable = unreachable; opener.unreachable = unreachable;
ListAppender<ILoggingEvent> appender = attach(); try (CapturedLog log = attach()) {
ReplyInbox inbox; ReplyInbox inbox = Fleetd.selectReplyInbox(broker, env, opener);
try { check.run(opener, log.events(), inbox);
inbox = Fleetd.selectReplyInbox(broker, env, opener);
} finally {
detach(appender);
} }
check.run(opener, appender, inbox);
} }
@FunctionalInterface @FunctionalInterface
private interface Check { private interface Check {
void run(RecordingAmqp opener, ListAppender<ILoggingEvent> appender, ReplyInbox inbox); void run(RecordingAmqp opener, List<ILoggingEvent> events, ReplyInbox inbox);
} }
} }
@@ -1,15 +1,12 @@
package dev.ltms.fleet.auth; package dev.ltms.fleet.auth;
import ch.qos.logback.classic.Level; 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.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper; import com.fasterxml.jackson.databind.ObjectMapper;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import static org.junit.jupiter.api.Assertions.*; import static org.junit.jupiter.api.Assertions.*;
@@ -24,28 +21,21 @@ import static org.junit.jupiter.api.Assertions.*;
class AuditLogTest { class AuditLogTest {
private final ObjectMapper mapper = new ObjectMapper(); private final ObjectMapper mapper = new ObjectMapper();
private ListAppender<ILoggingEvent> appender; private CapturedLog auditLog;
private ch.qos.logback.classic.Logger auditLogger;
@BeforeEach @BeforeEach
void attach() { void attach() {
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); auditLog = CapturedLog.at("audit", Level.INFO);
auditLogger = ctx.getLogger("audit");
appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
auditLogger.addAppender(appender);
auditLogger.setLevel(Level.INFO);
} }
@AfterEach @AfterEach
void detach() { void detach() {
auditLogger.detachAppender(appender); auditLog.close();
} }
private JsonNode onlyRecord() throws Exception { private JsonNode onlyRecord() throws Exception {
assertEquals(1, appender.list.size(), "exactly one audit line expected"); assertEquals(1, auditLog.events().size(), "exactly one audit line expected");
String line = appender.list.getFirst().getFormattedMessage(); String line = auditLog.events().getFirst().getFormattedMessage();
return mapper.readTree(line); // throws if the line is not valid JSON return mapper.readTree(line); // throws if the line is not valid JSON
} }
@@ -1,9 +1,7 @@
package dev.ltms.fleet.inject; package dev.ltms.fleet.inject;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent; 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.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper; import com.fasterxml.jackson.databind.ObjectMapper;
import dev.ltms.fleet.herdr.AgentControl; 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.Rendezvous;
import dev.ltms.fleet.msg.TestTurnTokens; import dev.ltms.fleet.msg.TestTurnTokens;
import dev.ltms.fleet.msg.TurnToken; import dev.ltms.fleet.msg.TurnToken;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import java.util.Set; import java.util.Set;
import java.util.regex.Pattern; 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 // 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 // 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. // resolves a caller's blocked send is at least WARN and must carry the reason.
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); try (CapturedLog log = CapturedLog.at(CompletionResolver.class, Level.WARN)) {
ch.qos.logback.classic.Logger resolverLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(CompletionResolver.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
resolverLog.addAppender(appender);
resolverLog.setLevel(Level.WARN);
try {
FakeHerdr herdr = new FakeHerdr().readText("stuck on an error screen"); FakeHerdr herdr = new FakeHerdr().readText("stuck on an error screen");
Rendezvous rendezvous = new Rendezvous(); Rendezvous rendezvous = new Rendezvous();
CompletionResolver resolver = new CompletionResolver(new AgentControl(herdr), rendezvous, ExhaustedPatternLookup.none(), ExhaustionSink.none()); CompletionResolver resolver = new CompletionResolver(new AgentControl(herdr), rendezvous, ExhaustedPatternLookup.none(), ExhaustionSink.none());
@@ -486,7 +476,7 @@ class CompletionResolverTest {
resolver.fail("term_a", null); resolver.fail("term_a", null);
String warn = appender.list.stream() String warn = log.events().stream()
.filter(e -> e.getLevel().equals(Level.WARN)) .filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.findFirst() .findFirst()
@@ -494,8 +484,6 @@ class CompletionResolverTest {
assertTrue(warn.contains("term_a"), "the log names the target: " + warn); 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(warn.contains("stuck on an error screen"), "the log carries the reason: " + warn);
assertTrue(waiter.isDone()); assertTrue(waiter.isDone());
} finally {
resolverLog.detachAppender(appender);
} }
} }
@@ -1,16 +1,14 @@
package dev.ltms.fleet.inject; package dev.ltms.fleet.inject;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent; 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.AgentControl;
import dev.ltms.fleet.herdr.AgentStatus; import dev.ltms.fleet.herdr.AgentStatus;
import dev.ltms.fleet.herdr.FakeHerdr; import dev.ltms.fleet.herdr.FakeHerdr;
import dev.ltms.fleet.herdr.HerdrException; import dev.ltms.fleet.herdr.HerdrException;
import dev.ltms.fleet.msg.TestTurnTokens; import dev.ltms.fleet.msg.TestTurnTokens;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import java.util.ArrayList; import java.util.ArrayList;
import java.util.List; import java.util.List;
@@ -493,23 +491,15 @@ class InjectorTest {
void readinessGraceExpiryIsLogged() { void readinessGraceExpiryIsLogged() {
// CB-562: the grace-expiry path used to clear the queue silently, so a message that never // 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 // 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.) // expiry now names the real cause. (CapturedLog pattern mirrors AuditLogTest.)
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) {
ch.qos.logback.classic.Logger injectorLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
injectorLog.addAppender(appender);
injectorLog.setLevel(Level.WARN);
try {
Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> {
}); });
inj.enqueue(T, "task", TestTurnTokens.inert(T)); inj.enqueue(T, "task", TestTurnTokens.inert(T));
for (int i = 0; i < READINESS_SAMPLES; i++) inj.onStatus(T, AgentStatus.IDLE); 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)) .filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.findFirst() .findFirst()
@@ -518,8 +508,6 @@ class InjectorTest {
assertTrue(warn.contains("never reached"), "the log names the real cause: " + warn); assertTrue(warn.contains("never reached"), "the log names the real cause: " + warn);
assertTrue(warn.contains("1 queued message"), assertTrue(warn.contains("1 queued message"),
"the log carries the failed message count: " + warn); "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 // 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 // READINESS_GRACE_POLLS or POLL_INTERVAL_MILLIS, so the assertion can't silently track a
// constant change instead of catching a real regression. // constant change instead of catching a real regression.
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) {
ch.qos.logback.classic.Logger injectorLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
injectorLog.addAppender(appender);
injectorLog.setLevel(Level.WARN);
try {
Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> {
}); });
inj.enqueue(T, "task", TestTurnTokens.inert(T)); inj.enqueue(T, "task", TestTurnTokens.inert(T));
for (int i = 0; i < READINESS_SAMPLES; i++) inj.onStatus(T, AgentStatus.IDLE); 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)) .filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.findFirst() .findFirst()
@@ -557,8 +537,6 @@ class InjectorTest {
"must print the measured poll count as a plain number: " + warn); "must print the measured poll count as a plain number: " + warn);
assertTrue(warn.contains("configured=240 polls/60s"), assertTrue(warn.contains("configured=240 polls/60s"),
"must print the configured budget, clearly labelled: " + warn); "must print the configured budget, clearly labelled: " + warn);
} finally {
injectorLog.detachAppender(appender);
} }
} }
@@ -584,22 +562,14 @@ class InjectorTest {
return readings[i]; return readings[i];
}; };
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) {
ch.qos.logback.classic.Logger injectorLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
injectorLog.addAppender(appender);
injectorLog.setLevel(Level.WARN);
try {
Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> false, _ -> {
}, stubClock); }, stubClock);
inj.enqueue(T, "task", TestTurnTokens.inert(T)); inj.enqueue(T, "task", TestTurnTokens.inert(T));
for (int i = 0; i < READINESS_SAMPLES; i++) inj.onStatus(T, AgentStatus.IDLE); 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)) .filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.findFirst() .findFirst()
@@ -609,8 +579,6 @@ class InjectorTest {
assertFalse(warn.contains("elapsed=60000ms"), "must not print " assertFalse(warn.contains("elapsed=60000ms"), "must not print "
+ "READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS (240 * 250 = 60000ms) as if it " + "READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS (240 * 250 = 60000ms) as if it "
+ "were the measured elapsed time: " + warn); + "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 // 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 // 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. // drop itself now names the cause and the number of messages it failed.
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); try (CapturedLog log = CapturedLog.at(Injector.class, Level.WARN)) {
ch.qos.logback.classic.Logger injectorLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(Injector.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
injectorLog.addAppender(appender);
injectorLog.setLevel(Level.WARN);
try {
Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> true, _ -> { Injector inj = new Injector(new AgentControl(herdr), TurnListener.NOOP, _ -> true, _ -> {
}); });
inj.enqueue(T, "orphan", TestTurnTokens.inert(T)); inj.enqueue(T, "orphan", TestTurnTokens.inert(T));
inj.drop(T, new HerdrException("worker gone", "pane_not_found", null)); 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)) .filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.findFirst() .findFirst()
@@ -669,8 +629,6 @@ class InjectorTest {
assertTrue(warn.contains(T), "the log names the target terminal: " + warn); 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("1 message"), "the log carries the failed message count: " + warn);
assertTrue(warn.contains("worker gone"), "the log carries the real cause: " + warn); assertTrue(warn.contains("worker gone"), "the log carries the real cause: " + warn);
} finally {
injectorLog.detachAppender(appender);
} }
} }
@@ -1,23 +1,22 @@
package dev.ltms.fleet.lead; package dev.ltms.fleet.lead;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent; 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.JsonNode;
import dev.ltms.fleet.config.FleetConfig; import dev.ltms.fleet.config.FleetConfig;
import dev.ltms.fleet.herdr.AgentControl; import dev.ltms.fleet.herdr.AgentControl;
import dev.ltms.fleet.herdr.FakeHerdr; import dev.ltms.fleet.herdr.FakeHerdr;
import dev.ltms.fleet.herdr.HerdrClient; import dev.ltms.fleet.herdr.HerdrClient;
import dev.ltms.fleet.herdr.HerdrException; import dev.ltms.fleet.herdr.HerdrException;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.DisplayName; import org.junit.jupiter.api.DisplayName;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.io.TempDir; import org.junit.jupiter.api.io.TempDir;
import org.slf4j.LoggerFactory;
import java.io.IOException; import java.io.IOException;
import java.nio.file.Files; import java.nio.file.Files;
import java.nio.file.Path; import java.nio.file.Path;
import java.util.List;
import java.util.concurrent.atomic.AtomicLong; import java.util.concurrent.atomic.AtomicLong;
import java.util.function.Function; import java.util.function.Function;
import java.util.function.LongSupplier; import java.util.function.LongSupplier;
@@ -862,25 +861,16 @@ class LeadRolloverTest {
// ---- fleetd #494: the log lines must print MEASURED values, never the configured budget -- // ---- fleetd #494: the log lines must print MEASURED values, never the configured budget --
private static ListAppender<ILoggingEvent> attachLog() { private static CapturedLog attachLog() {
Logger logger = (Logger) LoggerFactory.getLogger(LeadRollover.class); return CapturedLog.at(LeadRollover.class, Level.DEBUG);
logger.setLevel(Level.DEBUG);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.start();
logger.addAppender(appender);
return appender;
} }
private static void detachLog(ListAppender<ILoggingEvent> appender) { private static ILoggingEvent lastEventContaining(List<ILoggingEvent> events, String substring) {
((Logger) LoggerFactory.getLogger(LeadRollover.class)).detachAppender(appender); return events.stream()
}
private static ILoggingEvent lastEventContaining(ListAppender<ILoggingEvent> events, String substring) {
return events.list.stream()
.filter(e -> e.getFormattedMessage().contains(substring)) .filter(e -> e.getFormattedMessage().contains(substring))
.reduce((_, b) -> b) .reduce((_, b) -> b)
.orElseThrow(() -> new AssertionError("no log event contained \"" + substring .orElseThrow(() -> new AssertionError("no log event contained \"" + substring
+ "\"; got: " + events.list.stream().map(ILoggingEvent::getFormattedMessage).toList())); + "\"; got: " + events.stream().map(ILoggingEvent::getFormattedMessage).toList()));
} }
@Test @Test
@@ -914,15 +904,14 @@ class LeadRolloverTest {
AtomicLong clock = new AtomicLong(1_000); AtomicLong clock = new AtomicLong(1_000);
LeadRollover rollover = newRollover(flipsAfterClear, config, () -> clock.addAndGet(500)); LeadRollover rollover = newRollover(flipsAfterClear, config, () -> clock.addAndGet(500));
ListAppender<ILoggingEvent> events = attachLog(); try (CapturedLog log = attachLog()) {
try {
LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
assertTrue(decision.accepted(), "every synchronous gate passes; the refusal is logged " assertTrue(decision.accepted(), "every synchronous gate passes; the refusal is logged "
+ "only, deep inside the deferred continuation"); + "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()); assertEquals(Level.WARN, event.getLevel());
String message = event.getFormattedMessage(); String message = event.getFormattedMessage();
assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message); assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message);
@@ -934,8 +923,6 @@ class LeadRolloverTest {
+ message); + message);
assertFalse(message.contains("within 1s"), "must not present the configured budget as if " assertFalse(message.contains("within 1s"), "must not present the configured budget as if "
+ "it were the measured wait duration: " + message); + "it were the measured wait duration: " + message);
} finally {
detachLog(events);
} }
} }
@@ -954,15 +941,14 @@ class LeadRolloverTest {
AtomicLong clock = new AtomicLong(1_000); AtomicLong clock = new AtomicLong(1_000);
LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500)); LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500));
ListAppender<ILoggingEvent> events = attachLog(); try (CapturedLog log = attachLog()) {
try {
LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
assertTrue(decision.accepted(), "expected approval; got: " + decision.reason() assertTrue(decision.accepted(), "expected approval; got: " + decision.reason()
+ " / " + decision.detail()); + " / " + 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 " 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 " + "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)"); + "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)"), 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 " "must print the measured poll count and nudge count as plain numbers, not the "
+ "PICKUP_GRACE_POLLS constant standing in for either: " + message); + "PICKUP_GRACE_POLLS constant standing in for either: " + message);
} finally {
detachLog(events);
} }
} }
@@ -1000,15 +984,14 @@ class LeadRolloverTest {
AtomicLong clock = new AtomicLong(1_000); AtomicLong clock = new AtomicLong(1_000);
LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500)); LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500));
ListAppender<ILoggingEvent> events = attachLog(); try (CapturedLog log = attachLog()) {
try {
LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
assertTrue(decision.accepted(), "expected approval; got: " + decision.reason() assertTrue(decision.accepted(), "expected approval; got: " + decision.reason()
+ " / " + decision.detail()); + " / " + decision.detail());
ILoggingEvent event = lastEventContaining(events, "lead-rollover: rolled"); ILoggingEvent event = lastEventContaining(log.events(), "lead-rollover: rolled");
assertEquals(Level.INFO, event.getLevel()); assertEquals(Level.INFO, event.getLevel());
String message = event.getFormattedMessage(); String message = event.getFormattedMessage();
// fleetd #494 follow-up: waitUntilAtTurnBoundary now also reads the injected clock one // 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 " 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 " + "the whole roll — with this fixture's advancing clock, the full roll (turn-settle "
+ "wait + /clear wait + bootstrapText) took 7000ms: " + message); + "wait + /clear wait + bootstrapText) took 7000ms: " + message);
} finally {
detachLog(events);
} }
} }
@@ -1040,8 +1021,7 @@ class LeadRolloverTest {
AtomicLong clock = new AtomicLong(1_000); AtomicLong clock = new AtomicLong(1_000);
LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500)); LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500));
ListAppender<ILoggingEvent> events = attachLog(); try (CapturedLog log = attachLog()) {
try {
LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full"); LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true); 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 " + "only inside the deferred continuation, which this test's synchronous runner "
+ "has already run to completion by the time confirm() returns"); + "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()); assertEquals(Level.WARN, event.getLevel());
String message = event.getFormattedMessage(); String message = event.getFormattedMessage();
assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message); assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message);
@@ -1058,8 +1038,6 @@ class LeadRolloverTest {
+ "1s(=1000ms) configured budget: " + message); + "1s(=1000ms) configured budget: " + message);
assertFalse(message.contains("within 1s"), "must not present the configured budget as if " assertFalse(message.contains("within 1s"), "must not present the configured budget as if "
+ "it were the measured wait duration: " + message); + "it were the measured wait duration: " + message);
} finally {
detachLog(events);
} }
} }
} }
@@ -1,17 +1,17 @@
package dev.ltms.fleet.msg; package dev.ltms.fleet.msg;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import com.rabbitmq.client.Channel; import com.rabbitmq.client.Channel;
import com.rabbitmq.client.ConnectionFactory; import com.rabbitmq.client.ConnectionFactory;
import com.rabbitmq.client.impl.DefaultExceptionHandler; import com.rabbitmq.client.impl.DefaultExceptionHandler;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory; import org.slf4j.LoggerFactory;
import java.io.IOException; import java.io.IOException;
import java.lang.reflect.Proxy; import java.lang.reflect.Proxy;
import java.util.List;
import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicInteger;
import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertEquals;
@@ -32,21 +32,17 @@ class AmqpConnectionFailureLoggerTest {
assertEquals(AmqpConnectionFailureLogger.REPLY_INBOX, inboxHandler.connectionName()); assertEquals(AmqpConnectionFailureLogger.REPLY_INBOX, inboxHandler.connectionName());
assertEquals(AmqpConnectionFailureLogger.LEAD_MAILBOX, mailboxHandler.connectionName()); assertEquals(AmqpConnectionFailureLogger.LEAD_MAILBOX, mailboxHandler.connectionName());
ListAppender<ILoggingEvent> inboxEvents = attach(AmqpReplyInbox.class);
ListAppender<ILoggingEvent> mailboxEvents = attach(LeadMailbox.class);
IllegalStateException inboxFailure = new IllegalStateException("inbox failure"); IllegalStateException inboxFailure = new IllegalStateException("inbox failure");
IllegalStateException mailboxFailure = new IllegalStateException("mailbox failure"); IllegalStateException mailboxFailure = new IllegalStateException("mailbox failure");
try { try (CapturedLog inboxLog = attach(AmqpReplyInbox.class);
CapturedLog mailboxLog = attach(LeadMailbox.class)) {
inboxHandler.handleUnexpectedConnectionDriverException(null, inboxFailure); inboxHandler.handleUnexpectedConnectionDriverException(null, inboxFailure);
mailboxHandler.handleConnectionRecoveryException(null, mailboxFailure); 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"); 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"); mailboxFailure, "mailbox recovery line");
} finally {
detach(AmqpReplyInbox.class, inboxEvents);
detach(LeadMailbox.class, mailboxEvents);
} }
} }
@@ -54,17 +50,14 @@ class AmqpConnectionFailureLoggerTest {
void connectionResetKeepsForgivingHandlerWarningSemantics() { void connectionResetKeepsForgivingHandlerWarningSemantics() {
AmqpConnectionFailureLogger handler = new AmqpConnectionFailureLogger( AmqpConnectionFailureLogger handler = new AmqpConnectionFailureLogger(
AmqpConnectionFailureLogger.REPLY_INBOX, LoggerFactory.getLogger(AmqpReplyInbox.class)); AmqpConnectionFailureLogger.REPLY_INBOX, LoggerFactory.getLogger(AmqpReplyInbox.class));
ListAppender<ILoggingEvent> events = attach(AmqpReplyInbox.class); try (CapturedLog log = attach(AmqpReplyInbox.class)) {
try {
handler.handleUnexpectedConnectionDriverException(null, new IOException("Connection reset")); handler.handleUnexpectedConnectionDriverException(null, new IOException("Connection reset"));
assertEquals(1, events.list.size(), "the handler must still log a reset"); assertEquals(1, log.events().size(), "the handler must still log a reset");
ILoggingEvent event = events.list.getFirst(); ILoggingEvent event = log.events().getFirst();
assertEquals(Level.WARN, event.getLevel(), "ForgivingExceptionHandler logs connection resets at WARN"); assertEquals(Level.WARN, event.getLevel(), "ForgivingExceptionHandler logs connection resets at WARN");
assertEquals("AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred " assertEquals("AMQP connection fleetd-reply-inbox: An unexpected connection driver error occurred "
+ "(Exception message: Connection reset)", event.getFormattedMessage()); + "(Exception message: Connection reset)", event.getFormattedMessage());
assertTrue(event.getThrowableProxy() == null, "ForgivingExceptionHandler does not attach a reset stack trace"); 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"); "all exception-handling methods must remain inherited from DefaultExceptionHandler");
} }
private static ListAppender<ILoggingEvent> attach(Class<?> owner) { private static CapturedLog attach(Class<?> owner) {
Logger logger = (Logger) LoggerFactory.getLogger(owner); return CapturedLog.at(owner, Level.DEBUG);
logger.setLevel(Level.DEBUG);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.start();
logger.addAppender(appender);
return appender;
}
private static void detach(Class<?> owner, ListAppender<ILoggingEvent> appender) {
((Logger) LoggerFactory.getLogger(owner)).detachAppender(appender);
} }
private static AmqpConnectionFailureLogger installedStrictHandler(ConnectionFactory factory, String connection) { private static AmqpConnectionFailureLogger installedStrictHandler(ConnectionFactory factory, String connection) {
@@ -123,9 +107,9 @@ class AmqpConnectionFailureLoggerTest {
return assertInstanceOf(AmqpConnectionFailureLogger.class, factory.getExceptionHandler()); return assertInstanceOf(AmqpConnectionFailureLogger.class, factory.getExceptionHandler());
} }
private static void assertError(ListAppender<ILoggingEvent> events, String message, Throwable cause, String name) { private static void assertError(List<ILoggingEvent> events, String message, Throwable cause, String name) {
assertEquals(1, events.list.size(), name); assertEquals(1, events.size(), name);
ILoggingEvent event = events.list.getFirst(); ILoggingEvent event = events.getFirst();
assertEquals(Level.ERROR, event.getLevel(), name); assertEquals(Level.ERROR, event.getLevel(), name);
assertEquals(message, event.getFormattedMessage(), name); assertEquals(message, event.getFormattedMessage(), name);
assertEquals(cause.toString(), event.getThrowableProxy().getClassName() + ": " assertEquals(cause.toString(), event.getThrowableProxy().getClassName() + ": "
@@ -1,16 +1,13 @@
package dev.ltms.fleet.session; package dev.ltms.fleet.session;
import ch.qos.logback.classic.Level; 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.IThrowableProxy;
import ch.qos.logback.classic.spi.ILoggingEvent; 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.AfterEach;
import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.io.TempDir; import org.junit.jupiter.api.io.TempDir;
import org.slf4j.LoggerFactory;
import java.io.IOException; import java.io.IOException;
import java.nio.charset.StandardCharsets; 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 // ---- 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. ---- // non-SSH scheme. Reporting only, additive to the origin/https strip-and-refuse tests above. ----
private Logger reportingLogger; private CapturedLog reportingLog;
private ListAppender<ILoggingEvent> reportingAppender;
/** {@link GitWorktrees}'s own logger, captured fresh for each test so assertions never see a /** {@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 @BeforeEach
void attachReportingLogCapture() { void attachReportingLogCapture() {
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); reportingLog = CapturedLog.at(GitWorktrees.class, Level.WARN);
reportingLogger = ctx.getLogger(GitWorktrees.class);
reportingLogger.setLevel(Level.WARN);
reportingAppender = new ListAppender<>();
reportingAppender.setContext(ctx);
reportingAppender.start();
reportingLogger.addAppender(reportingAppender);
} }
@AfterEach @AfterEach
void detachReportingLogCapture() { void detachReportingLogCapture() {
reportingLogger.detachAppender(reportingAppender); reportingLog.close();
} }
private List<String> capturedMessages() { private List<String> 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 /** 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 * message either — the constraint is that a credential must never reach a log, however it
* would have gotten there. */ * would have gotten there. */
private void assertNoLeak(String secret) { private void assertNoLeak(String secret) {
for (ILoggingEvent event : reportingAppender.list) { for (ILoggingEvent event : reportingLog.events()) {
assertFalse(event.getFormattedMessage().contains(secret), assertFalse(event.getFormattedMessage().contains(secret),
"log message leaked a credential (" + secret + "): " + event.getFormattedMessage()); "log message leaked a credential (" + secret + "): " + event.getFormattedMessage());
IThrowableProxy thrown = event.getThrowableProxy(); IThrowableProxy thrown = event.getThrowableProxy();
@@ -596,7 +590,7 @@ class GitWorktreesTest {
new GitWorktrees(tmp.resolve("wts").toString()).add(repo.toString(), "cb-189-d", "HEAD"); 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" "expected no report for an ssh remote and a credential-free https remote, got:\n"
+ capturedMessages()); + capturedMessages());
} }
@@ -812,7 +806,7 @@ class GitWorktreesTest {
/** Criterion 1, all three present: the summary names the denominator and every neutralized file. */ /** Criterion 1, all three present: the summary names the denominator and every neutralized file. */
@Test @Test
void isolateToolSurfaceLogsAllThreeConfigsNeutralized(@TempDir Path tmp) throws Exception { void isolateToolSurfaceLogsAllThreeConfigsNeutralized(@TempDir Path tmp) throws Exception {
reportingLogger.setLevel(Level.INFO); reportingLog.setLevel(Level.INFO);
Path repo = initRepoWithAllThreeConfigs(tmp.resolve("repo")); Path repo = initRepoWithAllThreeConfigs(tmp.resolve("repo"));
new GitWorktrees(tmp.resolve("wts").toString()).add(repo.toString(), "cb-134-log-all", "HEAD"); 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. */ /** Criterion 1, two absent: the summary must still name the denominator and say why. */
@Test @Test
void isolateToolSurfaceLogsAbsentConfigsWithReason(@TempDir Path tmp) throws Exception { 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 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"); 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. */ /** Criterion 2: both candidates present — the summary line names both and the denominator. */
@Test @Test
void overlayParityLogsBothCopiedWhenBothCandidatesArePresent(@TempDir Path tmp) throws Exception { void overlayParityLogsBothCopiedWhenBothCandidatesArePresent(@TempDir Path tmp) throws Exception {
reportingLogger.setLevel(Level.INFO); reportingLog.setLevel(Level.INFO);
Path repo = initRepo(tmp.resolve("repo")); Path repo = initRepo(tmp.resolve("repo"));
Files.writeString(repo.resolve(".env"), "A=1\n"); Files.writeString(repo.resolve(".env"), "A=1\n");
Files.writeString(repo.resolve(".envrc"), "export 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. */ * denominator, and why the other candidate was not copied. */
@Test @Test
void overlayParityLogsOneCopiedOneAbsent(@TempDir Path tmp) throws Exception { void overlayParityLogsOneCopiedOneAbsent(@TempDir Path tmp) throws Exception {
reportingLogger.setLevel(Level.INFO); reportingLog.setLevel(Level.INFO);
Path repo = initRepo(tmp.resolve("repo")); Path repo = initRepo(tmp.resolve("repo"));
Files.writeString(repo.resolve(".env"), "A=1\n"); Files.writeString(repo.resolve(".env"), "A=1\n");
// .envrc deliberately not created — the absent candidate. // .envrc deliberately not created — the absent candidate.
@@ -1472,7 +1466,7 @@ class GitWorktreesTest {
* change, silently, unless this line told it so beforehand. */ * change, silently, unless this line told it so beforehand. */
@Test @Test
void overlayParityLogsSkipWorktreeConsequenceForATrackedFile(@TempDir Path tmp) throws Exception { void overlayParityLogsSkipWorktreeConsequenceForATrackedFile(@TempDir Path tmp) throws Exception {
reportingLogger.setLevel(Level.INFO); reportingLog.setLevel(Level.INFO);
Path repo = initRepo(tmp.resolve("repo")); Path repo = initRepo(tmp.resolve("repo"));
Files.writeString(repo.resolve(".env"), "A=1\n"); Files.writeString(repo.resolve(".env"), "A=1\n");
git(repo, "add", ".env"); git(repo, "add", ".env");
@@ -1495,7 +1489,7 @@ class GitWorktreesTest {
/** Criterion 5: null and empty overlay lists return quietly — no exception, no log noise. */ /** Criterion 5: null and empty overlay lists return quietly — no exception, no log noise. */
@Test @Test
void overlayParityWithNoCandidatesLogsNothing(@TempDir Path tmp) throws Exception { void overlayParityWithNoCandidatesLogsNothing(@TempDir Path tmp) throws Exception {
reportingLogger.setLevel(Level.INFO); reportingLog.setLevel(Level.INFO);
Path repo = initRepo(tmp.resolve("repo")); Path repo = initRepo(tmp.resolve("repo"));
Path wt = bareWorktree(repo, tmp.resolve("wt"), "cb134-empty"); Path wt = bareWorktree(repo, tmp.resolve("wt"), "cb134-empty");
GitWorktrees worktrees = new GitWorktrees(tmp.resolve("wts").toString()); 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(), null);
worktrees.overlayParity(repo.toString(), wt.toString(), List.of()); 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()); "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. */ * denominator, what was seeded, and what was kept because the repo already had it. */
@Test @Test
void seedSkillsLogsSeededAndKept(@TempDir Path tmp) throws Exception { void seedSkillsLogsSeededAndKept(@TempDir Path tmp) throws Exception {
reportingLogger.setLevel(Level.INFO); reportingLog.setLevel(Level.INFO);
Path repo = tmp.resolve("repo"); Path repo = tmp.resolve("repo");
Files.createDirectories(repo); Files.createDirectories(repo);
git(repo, "init", "-q", "-b", "main"); git(repo, "init", "-q", "-b", "main");
@@ -1,9 +1,7 @@
package dev.ltms.fleet.session; package dev.ltms.fleet.session;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent; 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.MemberRegistry;
import dev.ltms.fleet.auth.MemberLifecycle; import dev.ltms.fleet.auth.MemberLifecycle;
import dev.ltms.fleet.config.ConfigRef; 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.BackendQuarantine;
import dev.ltms.fleet.placement.PlacementDecision; import dev.ltms.fleet.placement.PlacementDecision;
import dev.ltms.fleet.placement.PlacementPolicies; import dev.ltms.fleet.placement.PlacementPolicies;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.AfterAll; import org.junit.jupiter.api.AfterAll;
import org.junit.jupiter.api.BeforeAll; import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.MethodOrderer; import org.junit.jupiter.api.MethodOrderer;
@@ -123,54 +122,8 @@ class SessionManagerTest {
return new SessionManager(workers, worktrees, clock); return new SessionManager(workers, worktrees, clock);
} }
/** // fleetd #529: CapturedLog moved to dev.ltms.fleet.testing.CapturedLog (imported above) so
* fleetd #525: captures a logger's output and, on {@link #close}, restores <em>both</em> the // every test file shares one implementation instead of each hand-rolling its own capture.
* appender and the level to what they were before. A bare {@code addAppender}/{@code
* setLevel} pair whose {@code finally} only detaches the appender leaves the level pinned —
* {@code ch.qos.logback.classic.Logger} instances are cached per class and shared across the
* whole JVM, so a level set by one test in this class is still in effect for every test that
* runs after it, in this class or any other. try-with-resources makes "restored the appender
* but not the level" impossible to write, because there is only one thing to close.
*/
private static final class CapturedLog implements AutoCloseable {
private final ch.qos.logback.classic.Logger logger;
private final Level originalLevel;
private final ListAppender<ILoggingEvent> appender;
private CapturedLog(Class<?> loggerClass, Level pinnedLevel) {
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
this.logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(loggerClass);
this.originalLevel = logger.getLevel();
this.appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
logger.addAppender(appender);
if (pinnedLevel != null) {
logger.setLevel(pinnedLevel);
}
}
/** Capture {@code loggerClass}'s output, pinning its level to {@code pinnedLevel} for the
* duration of the try-with-resources block. */
static CapturedLog at(Class<?> loggerClass, Level pinnedLevel) {
return new CapturedLog(loggerClass, pinnedLevel);
}
/** Capture {@code loggerClass}'s output without changing its level. */
static CapturedLog of(Class<?> loggerClass) {
return new CapturedLog(loggerClass, null);
}
List<ILoggingEvent> events() {
return appender.list;
}
@Override
public void close() {
logger.detachAppender(appender);
logger.setLevel(originalLevel);
}
}
/** /**
* CB-581: a {@link Worktrees} test double whose {@code hasUncommitted} and {@code remove} can * CB-581: a {@link Worktrees} test double whose {@code hasUncommitted} and {@code remove} can
@@ -7,13 +7,17 @@ import dev.ltms.fleet.herdr.AgentControl;
import dev.ltms.fleet.herdr.FakeHerdr; import dev.ltms.fleet.herdr.FakeHerdr;
import dev.ltms.fleet.herdr.WorkspaceControl; import dev.ltms.fleet.herdr.WorkspaceControl;
import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import dev.ltms.fleet.member.ClaudeCodeLauncher; import dev.ltms.fleet.member.ClaudeCodeLauncher;
import dev.ltms.fleet.msg.TestTurnTokens; import dev.ltms.fleet.msg.TestTurnTokens;
import dev.ltms.fleet.peer.MemberRole; 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.Test;
import org.junit.jupiter.api.TestMethodOrder;
import org.slf4j.LoggerFactory; import org.slf4j.LoggerFactory;
import java.util.List; 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. * 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 * 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. * call by {@link FakeHerdr}, matching the project's fake-based test style.
*
* <p>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 { 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() { private static MemberRegistry members() {
return new MemberRegistry(new FleetConfig.Fleet(Map.of(), return new MemberRegistry(new FleetConfig.Fleet(Map.of(),
Map.of("architect", new FleetConfig.Slot("ltms-local")), 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. * path, the session, and the cause an operator needs to find the work.
*/ */
@Test @Test
@Order(1)
void releasePreservesDirtyWorktreeAndLogsWarn() { void releasePreservesDirtyWorktreeAndLogsWarn() {
FakeHerdr herdr = new FakeHerdr(); FakeHerdr herdr = new FakeHerdr();
FakeWorktrees worktrees = new FakeWorktrees().withRepoRoot("/repo").withPrefix("/wt") FakeWorktrees worktrees = new FakeWorktrees().withRepoRoot("/repo").withPrefix("/wt")
@@ -262,21 +299,13 @@ class WorktreeSessionManagerTest {
MemberSession s = sessions.acquire("ltms-local", null, "/caller/proj", null, MemberSession s = sessions.acquire("ltms-local", null, "/caller/proj", null,
new WorktreeRequest("cb-576", null)); new WorktreeRequest("cb-576", null));
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory(); try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.WARN)) {
ch.qos.logback.classic.Logger sessionLog =
(ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SessionManager.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
sessionLog.addAppender(appender);
sessionLog.setLevel(Level.WARN);
try {
sessions.release(s.paneId()); sessions.release(s.paneId());
assertTrue(herdr.called("pane.close"), "release still tears the worker pane down"); assertTrue(herdr.called("pane.close"), "release still tears the worker pane down");
assertTrue(worktrees.removeCalls().isEmpty(), assertTrue(worktrees.removeCalls().isEmpty(),
"a dirty worktree is never removed — it holds the only copy of the work"); "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)) .filter(e -> e.getLevel().equals(Level.WARN))
.map(ILoggingEvent::getFormattedMessage) .map(ILoggingEvent::getFormattedMessage)
.filter(m -> m.contains("dirty worktree")) .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.worktree()), "the WARN names the worktree path: " + warn);
assertTrue(warn.contains(s.terminalId()), "the WARN names the session: " + warn); assertTrue(warn.contains(s.terminalId()), "the WARN names the session: " + warn);
assertTrue(warn.contains("COMPLETED"), "the WARN names the release cause: " + 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.
*
* <p>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, * 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. * {@code git worktree prune}, an earlier half-completed release) must not break teardown.
@@ -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 <em>both</em> the appender and the level to
* what they were before.
*
* <p>{@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.
*
* <p>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<ILoggingEvent> 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<ILoggingEvent> 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);
}
}