fleet/fleetd
3
0
Fork 0
Code Issues 73 Pull Requests Actions Packages Projects Releases 1 Wiki Activity

fleetd #529: promote CapturedLog to a shared test helper, close the logger-level leak #533

Merged
ltms merged 1 commits from worker/529-logger-level-sweep-2a5533-8 into main 2026-09-12 07:57:25 +02:00
Conversation 0 Commits 1 Files Changed 11
+272 -317
11 changed files with 272 additions and 317 deletions
Download Patch File Download Diff File Expand all files Collapse all files
fleetd/src/test/java/dev/ltms/fleet/FleetdAwaitHerdrTest.java
+11 -31
View File
@@ -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<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> attach() {
Logger logger = (Logger) LoggerFactory.getLogger(Fleetd.class);
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);
private static CapturedLog attach() {
return CapturedLog.at(Fleetd.class, Level.DEBUG);
}
}
fleetd/src/test/java/dev/ltms/fleet/FleetdReplyInboxSelectionTest.java
+28 -46
View File
@@ -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<ILoggingEvent> 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<ILoggingEvent> appender = new ListAppender<>();
appender.start();
logger.addAppender(appender);
return appender;
return CapturedLog.at(Fleetd.class, Level.INFO);
}
private static void detach(ListAppender<ILoggingEvent> appender) {
((Logger) LoggerFactory.getLogger(Fleetd.class)).detachAppender(appender);
}
private static void assertNoLogContains(ListAppender<ILoggingEvent> appender, String secret) {
assertTrue(appender.list.stream().noneMatch(e -> e.getFormattedMessage().contains(secret)),
private static void assertNoLogContains(List<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> appender, String fragment) {
return appender.list.stream().anyMatch(e ->
private boolean hasWarnContaining(List<ILoggingEvent> 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<String, String> env, boolean unreachable, Check check) {
RecordingAmqp opener = new RecordingAmqp();
opener.unreachable = unreachable;
ListAppender<ILoggingEvent> 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<ILoggingEvent> appender, ReplyInbox inbox);
void run(RecordingAmqp opener, List<ILoggingEvent> events, ReplyInbox inbox);
}
}
fleetd/src/test/java/dev/ltms/fleet/auth/AuditLogTest.java
+6 -16
View File
@@ -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<ILoggingEvent> 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
}
fleetd/src/test/java/dev/ltms/fleet/inject/CompletionResolverTest.java
+3 -15
View File
@@ -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<ILoggingEvent> 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);
}
}
fleetd/src/test/java/dev/ltms/fleet/inject/InjectorTest.java
+10 -52
View File
@@ -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<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> 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);
}
}
fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java
+15 -37
View File
@@ -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<ILoggingEvent> attachLog() {
Logger logger = (Logger) LoggerFactory.getLogger(LeadRollover.class);
logger.setLevel(Level.DEBUG);
ListAppender<ILoggingEvent> 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<ILoggingEvent> appender) {
((Logger) LoggerFactory.getLogger(LeadRollover.class)).detachAppender(appender);
}
private static ILoggingEvent lastEventContaining(ListAppender<ILoggingEvent> events, String substring) {
return events.list.stream()
private static ILoggingEvent lastEventContaining(List<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> 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);
}
}
}
fleetd/src/test/java/dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java
+14 -30
View File
@@ -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<ILoggingEvent> inboxEvents = attach(AmqpReplyInbox.class);
ListAppender<ILoggingEvent> 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<ILoggingEvent> 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<ILoggingEvent> attach(Class<?> owner) {
Logger logger = (Logger) LoggerFactory.getLogger(owner);
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 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<ILoggingEvent> events, String message, Throwable cause, String name) {
assertEquals(1, events.list.size(), name);
ILoggingEvent event = events.list.getFirst();
private static void assertError(List<ILoggingEvent> 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() + ": "
fleetd/src/test/java/dev/ltms/fleet/session/GitWorktreesTest.java
+20 -26
View File
@@ -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<ILoggingEvent> 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<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
* 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");
fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java
+3 -50
View File
@@ -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 <em>both</em> the
* appender and the level to what they were before. A bare {@code addAppender}/{@code
* setLevel} pair whose {@code finally} only detaches the appender leaves the level pinned —
* {@code ch.qos.logback.classic.Logger} instances are cached per class and shared across the
* whole JVM, so a level set by one test in this class is still in effect for every test that
* runs after it, in this class or any other. try-with-resources makes "restored the appender
* but not the level" impossible to write, because there is only one thing to close.
*/
private static final class CapturedLog implements AutoCloseable {
private final ch.qos.logback.classic.Logger logger;
private final Level originalLevel;
private final ListAppender<ILoggingEvent> appender;
private CapturedLog(Class<?> loggerClass, Level pinnedLevel) {
LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();
this.logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(loggerClass);
this.originalLevel = logger.getLevel();
this.appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
logger.addAppender(appender);
if (pinnedLevel != null) {
logger.setLevel(pinnedLevel);
}
}
/** Capture {@code loggerClass}'s output, pinning its level to {@code pinnedLevel} for the
* duration of the try-with-resources block. */
static CapturedLog at(Class<?> loggerClass, Level pinnedLevel) {
return new CapturedLog(loggerClass, pinnedLevel);
}
/** Capture {@code loggerClass}'s output without changing its level. */
static CapturedLog of(Class<?> loggerClass) {
return new CapturedLog(loggerClass, null);
}
List<ILoggingEvent> events() {
return appender.list;
}
@Override
public void close() {
logger.detachAppender(appender);
logger.setLevel(originalLevel);
}
}
// 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
fleetd/src/test/java/dev/ltms/fleet/session/WorktreeSessionManagerTest.java
+70 -14
View File
@@ -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.
*
* <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 {
/**
* 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<ILoggingEvent> appender = new ListAppender<>();
appender.setContext(ctx);
appender.start();
sessionLog.addAppender(appender);
sessionLog.setLevel(Level.WARN);
try {
try (CapturedLog log = CapturedLog.at(SessionManager.class, Level.WARN)) {
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.
*
* <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,
* {@code git worktree prune}, an earlier half-completed release) must not break teardown.
fleetd/src/test/java/dev/ltms/fleet/testing/CapturedLog.java
+92
View File
@@ -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);
}
}