Compare commits

...

8 Commits

Author SHA1 Message Date
Dai Ha 202e37e3b3 fleetd #537: pin CapturedLog.close()'s appender-detach and setLevel-immunity contracts
CI / contract (pull_request) Successful in 1m2s
CI / build (pull_request) Successful in 1m36s
Only the level-restore half of close() was pinned before this
(WorktreeSessionManagerTest). Deleting logger.detachAppender(appender)
from close() left mvn clean install green (1701 tests, 0 failures) --
the appender-detach half of the contract was unmeasured.

Adds CapturedLogTest with three tests, each using a logger name no
production class uses:
- closeDetachesTheAppenderSoALaterLogIsNotCaptured: an event logged
  after close() must not land in events().
- closeRestoresTheLevelCapturedAtOpen: the helper's headline contract
  in one place, independent of any production class.
- setLevelDuringCaptureDoesNotChangeWhatCloseRestores: setLevel()'s
  own javadoc claim that close() always restores the level captured
  at construction, never a value set through setLevel() mid-capture.

Test-only change; CapturedLog.java itself is untouched.
2026-09-12 13:36:55 +07:00
ltms f1640f5dcc Merge pull request 'fleetd #535: convert FleetdLeadMailboxSelectionTest to CapturedLog' (#536) from worker/535-appender-leak-fe74c1-1 into main
CI / contract (push) Successful in 1m13s
CI / build (push) Successful in 1m28s
2026-09-12 08:25:01 +02:00
Dai Ha c7903c1efe fleetd #535: convert FleetdLeadMailboxSelectionTest to CapturedLog
CI / contract (pull_request) Successful in 53s
CI / build (pull_request) Successful in 1m52s
Three call sites (captureFleetdLogs at :55) attached a ListAppender to the
Fleetd.class logger with addAppender and never detached it, and never
called appender.setContext(...) either. Logback Logger instances are
cached per class and shared for the whole JVM, and surefire reuses forks,
so all three appenders stayed attached for every later test in the fork.

Convert all three call sites to CapturedLog.of(Fleetd.class) (added in
#533) via try-with-resources, which detaches the appender and sets the
context for free. Delete captureFleetdLogs(); nothing calls it now.
2026-09-12 13:17:21 +07:00
ltms 7d711942fe Merge #534: detect a died shutdown drain the ERROR count is blind to (fleetd #512 part 2)
CI / contract (push) Successful in 48s
CI / build (push) Successful in 1m52s
Verified independently. The branch is based on 8335b12 while main is at bec87f9, so I merged locally first and tested the MERGED tree, not the branch — a clean auto-merge is not a working merge.

Merged tree checks:
- `bash -n` exit 0 on both scripts, under /bin/bash 3.2.57 and env bash 5.3.9.
- Suite exit 0, 0 lines matching `^FAIL:`, 255 bytes of output. 60 test functions defined, 60 invoked, and no defined-but-never-invoked orphan (checked with a comm against the invocation list, not by comparing two counts — two equal counts can both be wrong).
- My own comment fix from bec87f9 survived the merge and is still at :317.

I ran two mutations the worker did not, per "mutate the half the worker did not":

(A) The one that matters, because it is the defect this ticket exists to prevent: collapsed the `unknown` state into `complete`, so "cannot tell" reports as a pass. Result exit 1, one FAIL: `cannot-tell fixture must set REDEPLOY_DRAIN_STATE=unknown: expected unknown, got complete`. So the third state is genuinely load-bearing, not decoration.

(B) Broke the positive check: changed `find_drain_complete_line`'s pattern from `drain complete: released=` to `drain finished: released=`, one site. Result exit 1, one FAIL: `find_drain_complete_line did not capture the present line`.

Proof that (B) applied, against a pristine copy: the full grep line 1 -> 0, the mutant form 0 -> 1, and the bare phrase 2 -> 1 with the comment occurrence untouched. Both files restored byte-identical; `git diff --quiet` clean; green control re-run.

A note on my own proof cell for (B), because it was wrong the first time. I wrote the counts with escaped double quotes inside an already double-quoted command substitution, so the shell split the pattern on spaces and grep treated the words as filenames. It printed "2 and 2" alongside `ugrep: No such file or directory` warnings — a symmetric, plausible-looking pair that meant nothing. The kill itself was never in doubt, since the suite named the exact function, but the cell that was supposed to prove the mutation applied proved nothing. Re-done with single quotes. This is the same trap already written down for this repo, hit by me, in a cell whose only purpose was to guard against exactly this.

One thing I checked that no test covers: the main flow's `HAD_OLD_PID=0; [ -n "$OLD_PID" ] && HAD_OLD_PID=1` runs under `set -euo pipefail`, and on a cold start the test fails. Sourcing stops before the main flow, so no behavioural test reaches that line. If `set -e` fired there, every cold start would abort before the health checks. It does not: `set -e` exempts the left side of an `&&` list, confirmed by running it under both shells — `survived, HAD_OLD_PID=0` on 3.2.57 and on 5.3.9. Safe, but it is untested main-flow wiring, which is the same class as #528's item 1 and belongs on that list.

On the `n/a` fourth state, which the worker flagged for a reviewer's judgment rather than quietly keeping: accepted, and it is in scope. The ticket asked for a third state because a sentinel conflating "no" with "cannot tell" hides two causes needing opposite handling. "The question does not apply" is a third such cause, not a variant of "cannot tell". Without it, the new warning would fire on every clean cold start, and a warning that cries wolf on the most common path trains the operator to skip it — which destroys the absence signal just as surely as putting the completion line in a `finally` would. The worker also proved the gate is actually consulted, using a cold-start fixture whose content deliberately looks like a died drain, so the test would fail if the gate were skipped. That is the right way to test a gate.

Both remaining outcomes are correctly excluded from the "no ERROR lines since restart" summary: only `complete` and `n/a` let it print.
2026-09-12 08:04:15 +02:00
Dai Ha bec87f987c scripts: name the mechanism in detect_supervisor's constraint 2, not a line number
CI / contract (push) Successful in 1m30s
CI / build (push) Successful in 1m33s
Constraint 2 read "This script runs under `set -euo pipefail` (line 50), so an
unset variable is a loud failure." Two problems, both small and both the same
family as fleetd #494 — a comment that states the wrong reason.

The line number was stale: the `set` line is at 54, not 50. It was the only
line-number citation in the file, and a citation like that goes stale on the
next insert above it, silently, with nothing to catch it.

The mechanism was also misattributed. What makes an unset variable a loud
failure is `set -u`. Naming the whole `-euo pipefail` string invites the reader
to credit pipefail for it, which is the mistake fleet01 flagged on a different
cell this week: pipefail is insurance against a future pipeline stage, not what
catches the current shape.

Now names `set -u` and says where it is without a number, and records why the
number is gone so nobody adds one back.

Comment only. bash -n exit 0 under /bin/bash 3.2.57 and env bash 5.3.9;
scripts/test-redeploy-fleetd.sh exit 0 with 0 lines matching ^FAIL:.
2026-09-12 12:58:37 +07:00
Dai Ha 7f8a8829f9 fleetd #529 follow-up: the new helper's javadoc claimed a reach it does not have
CapturedLog's class javadoc said it is "the one way to pin or capture a logger's
level and output in this test tree". Measured on main at af95897, that is false:
nine test files still hand-roll the ListAppender + setLevel + finally
detachAppender pattern, with 42 setLevel calls on a raw logback Logger between
them.

None of those nine is a defect. Every one pairs its pin with a restore, so none
is the fleetd #525 leak, and #529's scope was the 19 unrestored pins only. The
problem is the sentence, not the code: a reader who believes "the one way" and
then greps finds nine counter-examples and cannot tell a leftover from a
violation. That is the same shape as a wrong reason in a comment — the text
survives while the fact under it moves.

Replaced with what is actually true: new code must use the helper, the pattern
still exists elsewhere, and here is the list plus the two commands that
re-measure it. The paragraph says to delete itself once the first command comes
back empty, rather than to keep a count up to date.

Javadoc only. mvn -f fleetd/pom.xml test-compile exit 0.
2026-09-12 12:58:26 +07:00
ltms af9589783e Merge #533: promote CapturedLog to a shared test helper and close the logger-level leak (fleetd #529)
CI / contract (push) Successful in 53s
CI / build (push) Successful in 1m35s
Verified independently in a scratch worktree at 8ea5c2b, not promoted from the worker's report.

Build: `mvn -f fleetd/pom.xml clean install` exit 0, `Tests run: 1701, Failures: 0, Errors: 0, Skipped: 0`, BUILD SUCCESS.

Base arithmetic, measured rather than carried forward: a6415f3 (this branch's parent) has 1695 `@Test` plus 2 parameterized/repeated, and the branch has 1696 plus 2 — a delta of exactly +1, matching the per-file count (WorktreeSessionManagerTest 24 -> 25). So 1700 -> 1701 is the one new proving test and nothing else. A number I had carried from earlier in the session said 1699; that number was wrong and is retired. No Java file differs between a6415f3 and main at 8335b12, so the base count is the same on both.

Mutation (a), the shared instrument: removed `logger.setLevel(originalLevel);` from `CapturedLog.close()`. Result exit 1, `Tests run: 25, Failures: 1`, the single failure being `sharedSessionManagerLoggerLevelIsRestoredAfterDirtyWorktreeReleasePinsWarn` with `expected: <TRACE> but was: <WARN>`. Restored byte-identical.

Mutation (b), the use site: replaced the try-with-resources in `releasePreservesDirtyWorktreeAndLogsWarn` with the pre-#525 hand-rolled `ListAppender` + `setLevel` + `finally detachAppender` pattern. Result exit 1, one failure, the same assertion. Restored byte-identical.

Green control on the restored tree: `git diff --quiet` clean, full suite exit 0, 1701/0/0/0.

Both mutants were killed, so per the economy fleet01 proposed and #529 adopted, neither needs a separate harness-proof cell — the kill is the proof the cell can go red.

Leak survey, re-measured here rather than taken from the report: on a6415f3, 9 files carry 19 `setLevel` pins on a raw logback `Logger` with zero restoring call; on the branch that set is empty. The 7 remaining `setLevel` calls in `GitWorktreesTest` are `reportingLog.setLevel(...)` on the `CapturedLog` instance, whose `close()` restores the original, so they are re-pins and not leaks.

File hashes match the worker's report exactly, head and tail: CapturedLog.java 486d6f5b5a30dc5ef7f75e5e10be353e720fb0de503825e88e8d96e30a61a2f7, WorktreeSessionManagerTest.java a722a98d828c82e00415d2a924d341e177ded704262aaa5963ea2d09a683df94.

Two things follow this merge rather than block it, both filed separately: one javadoc sentence in the new helper overstates its own reach, and the worker's item 4 reports a separate appender leak outside this ticket's scope.
2026-09-12 07:57:25 +02:00
Dai Ha 8ea5c2bb1f 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.
2026-09-12 12:48:49 +07:00
14 changed files with 424 additions and 359 deletions
@@ -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);
}
}
@@ -1,15 +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 dev.ltms.fleet.config.FleetConfig;
import dev.ltms.fleet.msg.LeadMailbox;
import dev.ltms.fleet.testing.CapturedLog;
import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import java.util.List;
import java.util.Map;
import static org.junit.jupiter.api.Assertions.*;
@@ -52,29 +49,22 @@ class FleetdLeadMailboxSelectionTest {
}
}
private static ListAppender<ILoggingEvent> captureFleetdLogs() {
Logger logger = (Logger) LoggerFactory.getLogger(Fleetd.class);
ListAppender<ILoggingEvent> appender = new ListAppender<>();
appender.start();
logger.addAppender(appender);
return appender;
}
private static String joined(ListAppender<ILoggingEvent> appender, Level level) {
return appender.list.stream().filter(e -> e.getLevel() == level)
private static String joined(CapturedLog captured, Level level) {
return captured.events().stream().filter(e -> e.getLevel() == level)
.map(ILoggingEvent::getFormattedMessage).reduce("", (a, b) -> a + "\n" + b);
}
@Test
void noCoordinatorBlockLeavesTheFeatureOffSilently() {
var appender = captureFleetdLogs();
var opener = new RecordingOpener();
try (var captured = CapturedLog.of(Fleetd.class)) {
var opener = new RecordingOpener();
assertNull(Fleetd.openLeadMailbox(null, Map.of(), opener));
assertNull(Fleetd.openLeadMailbox(null, Map.of(), opener));
assertNull(opener.offeredUri, "nothing configured means nothing is opened");
assertEquals("", joined(appender, Level.WARN),
"an opt-in feature nobody asked for must not warn on every boot");
assertNull(opener.offeredUri, "nothing configured means nothing is opened");
assertEquals("", joined(captured, Level.WARN),
"an opt-in feature nobody asked for must not warn on every boot");
}
}
@Test
@@ -114,31 +104,33 @@ class FleetdLeadMailboxSelectionTest {
@Test
void warnsAndStaysOffWhenSelfIdIsMissing() {
var appender = captureFleetdLogs();
var opener = new RecordingOpener();
var coordinator = new FleetConfig.Coordinator(RESOLVED_URI, null, null, null, null);
try (var captured = CapturedLog.of(Fleetd.class)) {
var opener = new RecordingOpener();
var coordinator = new FleetConfig.Coordinator(RESOLVED_URI, null, null, null, null);
assertNull(Fleetd.openLeadMailbox(coordinator, Map.of(), opener));
assertNull(Fleetd.openLeadMailbox(coordinator, Map.of(), opener));
assertNull(opener.offeredUri, "a mailbox with no owning coord-id has no queue to declare");
String warns = joined(appender, Level.WARN);
assertTrue(warns.contains("coordinator.selfId"), () -> "say which key is missing: " + warns);
assertFalse(warns.contains(SECRET), () -> "the URI's password must never be logged: " + warns);
assertNull(opener.offeredUri, "a mailbox with no owning coord-id has no queue to declare");
String warns = joined(captured, Level.WARN);
assertTrue(warns.contains("coordinator.selfId"), () -> "say which key is missing: " + warns);
assertFalse(warns.contains(SECRET), () -> "the URI's password must never be logged: " + warns);
}
}
@Test
void warnsAndStaysOffWhenTheBrokerIsUnreachableAtBoot() {
var appender = captureFleetdLogs();
var opener = new RecordingOpener();
opener.unreachable = true;
var coordinator = new FleetConfig.Coordinator(RESOLVED_URI, null, "mac-opus", null, null);
try (var captured = CapturedLog.of(Fleetd.class)) {
var opener = new RecordingOpener();
opener.unreachable = true;
var coordinator = new FleetConfig.Coordinator(RESOLVED_URI, null, "mac-opus", null, null);
assertNull(Fleetd.openLeadMailbox(coordinator, Map.of(), opener),
"a down coordination broker turns the feature off; it must never take the daemon down");
assertNull(Fleetd.openLeadMailbox(coordinator, Map.of(), opener),
"a down coordination broker turns the feature off; it must never take the daemon down");
String warns = joined(appender, Level.WARN);
assertTrue(warns.contains("coord.example"), () -> "name the host that failed: " + warns);
assertFalse(warns.contains(SECRET), () -> "with credentials stripped: " + warns);
assertTrue(warns.contains("Connection refused"), () -> "and the real reason: " + warns);
String warns = joined(captured, Level.WARN);
assertTrue(warns.contains("coord.example"), () -> "name the host that failed: " + warns);
assertFalse(warns.contains(SECRET), () -> "with credentials stripped: " + warns);
assertTrue(warns.contains("Connection refused"), () -> "and the real reason: " + warns);
}
}
}
@@ -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);
}
}
@@ -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
}
@@ -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);
}
}
@@ -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);
}
}
@@ -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);
}
}
}
@@ -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() + ": "
@@ -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");
@@ -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
@@ -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.
@@ -0,0 +1,112 @@
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>New code must use this rather than hand-rolling the {@code ListAppender} + {@code setLevel} +
* {@code finally detachAppender} pattern: use {@link #at} or {@link #of}. It is <em>not</em> yet
* the only instance of the pattern in this test tree, and the earlier wording here said it was —
* which would leave a reader who greps unable to tell a leftover from a violation.
*
* <p>Measured on main at af95897 (2026-09-12): nine test files still hand-roll it, with 42
* {@code setLevel} calls on a raw logback {@code Logger} between them — {@code
* FleetdStartupReportTest}, {@code GitHostShapeReportTest}, {@code MemberCredentialsGapReportTest},
* {@code MemberTrustModelReportTest}, {@code FleetHealthMonitorTest}, {@code
* ClaudeCodeLauncherTest}, {@code HerdrPeerLauncherAllowListWiringTest}, {@code
* HerdrPeerLauncherCharterTest} and {@code OpenCodeLauncherTest}. Every one of them pairs its pin
* with a restore, so none is the fleetd #525 leak and none was in fleetd #529's scope, which was
* the 19 <em>unrestored</em> pins only. They are unmigrated, not broken.
*
* <p>Re-measure with the two commands below, from the repo root. A file that appears in the first
* list and not the second still hand-rolls the pattern. When the first list comes back empty, this
* paragraph is spent and the sentence above can go back to saying "the one way" — delete the
* paragraph then rather than updating the count.
*
* <pre>{@code
* grep -rlE '\.setLevel\(' fleetd/src/test/java --include='*.java' | grep -v CapturedLog.java
* grep -rl 'CapturedLog' fleetd/src/test/java --include='*.java'
* }</pre>
*/
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);
}
}
@@ -0,0 +1,96 @@
package dev.ltms.fleet.testing;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import static org.junit.jupiter.api.Assertions.assertEquals;
/**
* fleetd #537: pins {@link CapturedLog#close}'s own contract — the appender detach half, the level
* restore half, and that {@link CapturedLog#setLevel} does not change what {@code close} restores.
* Before this, only the level-restore half was pinned (by {@code
* WorktreeSessionManagerTest.sharedSessionManagerLoggerLevelIsRestoredAfterDirtyWorktreeReleasePinsWarn}).
* Measured: deleting {@code logger.detachAppender(appender);} from {@code close()} still left
* {@code mvn clean install} green — 1701 tests, 0 failures — before this file existed.
*
* <p>Every test below uses a logger name no production class uses, and unique per test, so this
* file cannot become the next entry in fleetd #525's leak family: {@link CapturedLog}'s own
* javadoc re-measure commands (top of that file) would otherwise need to start naming this class.
*/
class CapturedLogTest {
/**
* The appender must be detached on close: an event logged through the raw logger after close
* must not land in {@link CapturedLog#events()}. Asserting on the observable list (rather than
* {@code logger.iteratorForAppenders()}) is what the ticket asked for, and it is also what a
* real leak would actually break — a later test's own {@code ListAppender} silently gaining
* events emitted by code under test that has nothing to do with it.
*/
@Test
void closeDetachesTheAppenderSoALaterLogIsNotCaptured() {
String loggerName = "capturedlog-test-only.appender-detach";
Logger rawLogger = (Logger) LoggerFactory.getLogger(loggerName);
CapturedLog log = CapturedLog.of(loggerName);
rawLogger.info("while open");
int eventsWhileOpen = log.events().size();
assertEquals(1, eventsWhileOpen, "the event logged while open must be captured");
log.close();
rawLogger.info("after close");
assertEquals(eventsWhileOpen, log.events().size(),
"close() must detach the appender: an event logged after close must not be "
+ "captured, but the captured list grew from " + eventsWhileOpen + " to "
+ log.events().size());
}
/**
* The helper's own headline contract, pinned in one place independent of any production
* class's behaviour: {@code close()} restores the level the logger had before {@link
* CapturedLog#at} pinned it.
*/
@Test
void closeRestoresTheLevelCapturedAtOpen() {
String loggerName = "capturedlog-test-only.level-restore";
Logger rawLogger = (Logger) LoggerFactory.getLogger(loggerName);
rawLogger.setLevel(Level.DEBUG);
CapturedLog log = CapturedLog.at(loggerName, Level.ERROR);
assertEquals(Level.ERROR, rawLogger.getLevel(), "the pinned level took effect while open");
log.close();
assertEquals(Level.DEBUG, rawLogger.getLevel(),
"close() must restore the level captured when at() was called (DEBUG), not leave "
+ "the pinned level (ERROR) in place");
}
/**
* {@link CapturedLog#setLevel}'s javadoc claims that re-pinning the level mid-capture does not
* change what {@code close()} restores — that restore always uses the level captured when the
* instance was created, never a value set through {@code setLevel}. Nothing checked this
* before: open with a pinned WARN, call {@code setLevel(TRACE)}, close, and the result must be
* the level from BEFORE {@code at} — neither WARN nor TRACE.
*/
@Test
void setLevelDuringCaptureDoesNotChangeWhatCloseRestores() {
String loggerName = "capturedlog-test-only.setlevel-no-effect";
Logger rawLogger = (Logger) LoggerFactory.getLogger(loggerName);
rawLogger.setLevel(Level.DEBUG);
CapturedLog log = CapturedLog.at(loggerName, Level.WARN);
log.setLevel(Level.TRACE);
assertEquals(Level.TRACE, rawLogger.getLevel(), "setLevel took effect immediately");
log.close();
assertEquals(Level.DEBUG, rawLogger.getLevel(),
"close() must restore the level captured at open (DEBUG) regardless of any "
+ "later setLevel() call: it must be neither WARN (the level pinned by "
+ "at()) nor TRACE (the level set via setLevel() mid-capture), but got "
+ rawLogger.getLevel());
}
}
+6 -4
View File
@@ -314,10 +314,12 @@ systemd_loaded() {
# never assigned to a global: a global set inside a `$( )` subshell dies with that subshell.
# This function packs BOTH values (kind and detail) onto that one stdout line, joined by
# $SUPERVISOR_DETAIL_SEP, and the caller unpacks them on its own side of the subshell boundary.
# 2. This script runs under `set -euo pipefail` (line 50), so an unset variable is a loud
# failure. Do not add a `${VAR:-default}` anywhere downstream to paper over a value that
# should always be there — that hides a lost value instead of surfacing it (fleetd #497's
# defect class).
# 2. This script runs under `set -u` (part of the `set -euo pipefail` at the top of the file), so
# an unset variable is a loud failure. Do not add a `${VAR:-default}` anywhere downstream to
# paper over a value that should always be there — that hides a lost value instead of
# surfacing it (fleetd #497's defect class). The mechanism is named rather than cited by line
# number on purpose: a line number in a comment goes stale on the next insert above it, and
# this one already had — it said line 50 while the `set` line was at 54.
# 3. Every `case` on this function's return value needs an explicit final `*)` arm, chosen by
# whether that caller ACTS on the value (`die` — an unrecognised value must never be silently
# driven) or only DISPLAYS it (`echo`/`warn` and continue — a diagnostic must not go silent on