Compare commits

...

12 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 190436c9cf fleetd #512 part 2: detect a died shutdown drain the ERROR count is blind to
CI / contract (pull_request) Successful in 1m15s
CI / build (pull_request) Successful in 2m4s
The previous daemon's dead shutdown drain (an uncaught exception in a
shutdown thread) never passes through the logger, so it never carries an
ERROR/SEVERE token, so redeploy-fleetd.sh's existing ERROR-count classifier
is structurally blind to it and prints a confident "no ERROR lines since
restart" while the drain actually died.

Add scan_uncaught_exceptions (greps the shutdown window for the failure's
real shape: `Exception in thread`, `NoClassDefFoundError`) and
find_drain_complete_line (checks for #522's SessionManager.drainAll
completion line). Compose both in report_shutdown_drain, a single
decision+action function the main flow calls unconditionally (same shape
as swap_if_built/refuse_drain_gate from #521/#528), which resolves to one
of four outcomes: complete, died, unknown ("cannot tell" — the line is
absent for either of two reasons that need opposite handling: the previous
daemon predates #522, or its drain failed without throwing), or n/a (no
previous daemon was actually stopped this run). Never fails the redeploy;
warns loudly instead.

Gate the "no ERROR lines since restart" summary line on the new outcome so
it never reads as reassurance when the drain died or the outcome is
"cannot tell" (item 4 of the ticket).

Tests: 11 new test functions (60 defined/invoked, was 49), covering both
pure classifiers, all four report_shutdown_drain outcomes, a source-grep
proof of the main-flow call site (sourcing stops before the main flow
runs), an ordering check, and the item-4 gating. Full suite green
(exit 0, 0 anchored FAIL lines). Five mutations applied and killed by hand
during review, each restored to a byte-identical file afterward.
2026-09-12 12:55:54 +07: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
ltms 8335b12562 Merge #532: pin drain_gate_refusal's call site, not just the predicate (fleetd #528)
CI / contract (push) Successful in 53s
CI / build (push) Successful in 1m47s
Verified independently in my own worktree at the pushed head 7c34e8f, not taken
from the worker's report. CI run 1781: success.

The shape is the one #528 asked for and the one #526 arrived at: refuse_drain_gate
composes the message via drain_gate_refusal AND calls die itself, and the main
flow calls it unconditionally at :710. No guard is left in the main flow to
remove, invert or bypass on its own.

My measurements:

  test functions defined / invoked   49 / 49   (was 44/44; +5)
  bash -n, /bin/bash 3.2.57          rc=0 on both files
  bash -n, env bash 5.3.9            rc=0 on both files
  clean control                      exit 0, 0 lines matching ^FAIL:, 256 bytes

Two mutations, both killed, each by a differently named failure:

  call site deleted (the item-1 mutation: :710 replaced by a flat
  die "aborted — nothing changed")
    -> exit 1, 1 ^FAIL: line, 87 bytes
       FAIL: could not find the main flow's refuse_drain_gate call site in redeploy-fleetd.sh

  refuse_drain_gate stops consulting the predicate (its body's
  die "$(drain_gate_refusal ...)" replaced by a flat message)
    -> exit 1, 1 ^FAIL: line
       FAIL: refuse_drain_gate build-ran+staged-present die message does not name the staged jar

The first cell is the point of the ticket. Before this change the same mutation
gave exit 0, zero FAIL lines and output byte-identical to a clean run at 256
bytes. It now exits 1 and names the missing call site. Each mutation was proven
applied with a uniquely tagged marker plus a second, different search string,
with a control against a pristine copy showing the exact inverse (1/0 mutated,
0/1 pristine), and the function definition confirmed still present so the
mutation targeted the call and not the function. Restored byte-identical to
0e5a99a22c9c65f72960d8f179ca5299307889e06bc42131f098a513e7b97bd6 and the final
control is green.

Needle uniqueness checked, because this is where it could have gone wrong:
grep -cF 'refuse_drain_gate "$DO_BUILD" "$JAR_STAGED"' on the production script
returns 1, at :710, the real call site. The worker hit the self-match trap while
writing the comment above refuse_drain_gate — their first draft quoted the
call-site string literally, which would have let the source-text test match the
comment instead of the call — caught it themselves, and reworded so the comment
cannot become a second match. That is the same trap that cost me a false pass on
a probe earlier today, and catching it unprompted is the better half of this PR.

The dead-check sweep came back as a real negative, with the reasoning shown
rather than asserted: of the five scripts under set -e with pipefail, every
pipe-into-assignment already carries || true or || echo, and the remaining two
scripts have no pipe-into-assignment at all. probe-member-credentials.sh and
deploy/herdr-inner.sh correctly excluded for not having set -e. No live
instances.

One inaccuracy in the report, in the report only: it abbreviates the restored
hash as "0e5a99a2...78f0a", and that tail does not occur in the actual hash,
which ends b97bd6. I hashed the committed file myself and confirmed the restore
matched, so the file is right and only the quoted abbreviation is wrong. Flagged
because an abbreviated hash that nobody can match against anything is worse than
no hash.

wait_for_daemon_exit's call site (item 2) stays open as the ticket scoped it —
source-text pinned only, "partially pinned, not audited". The seven untested
main-flow decisions are untouched; the worker correctly notes it changed the body
of one of those if blocks while leaving the guard condition itself untested, as
instructed.
2026-09-12 07:41:57 +02:00
ltms d25c863118 Merge #531: separate the blocked forge MCP server from the working GITEA_TOKEN
CI / build (push) Successful in 1m30s
CI / contract (push) Successful in 1m32s
Charter wording only — 9 insertions, 4 deletions, one file. CI run 1780 on
be07ed2: success.

Resolves the "charter may be stale" item I had been carrying. It was not stale.
Two workers reporting working forge access and the charter saying forge tools
hold a blocked credential were both correct, about two different credentials:
the repo-scoped GITEA_TOKEN the daemon injects (which opens every worker PR,
per implementer SKILL.md step 5) versus the forge MCP server that leaks in from
the operator's user-scope config (which is deliberately blocked). The wording
did not separate them, and a worker could have read it as "I cannot reach the
forge" and skipped opening its PR.

Both sentences now name the MCP server specifically and state that the injected
token is a separate, working route.

Canonical block and wiki template verified byte-identical after the edit — the
CLAUDE.md sync script reports "in sync: True". The wiki commit is d02a55d on
wiki's own main, pushed and verified by ref (ls-remote matched local HEAD), not
by exit code. The submodule pointer stayed unstaged.

Not re-measured in this change: that the blocked MCP credential does fail every
call. That claim is the existing charter's and I only narrowed what it refers
to. It would need its own probe with a request that cannot succeed on its
merits, so that a rejection can only mean the block.
2026-09-12 07:41:11 +02:00
Dai Ha 7c34e8f4f9 fleetd #528: pin drain_gate_refusal's call site, not just the predicate
CI / contract (pull_request) Successful in 53s
CI / build (pull_request) Successful in 1m31s
drain_gate_refusal composes the correct abort message and is well tested,
but the main flow built its own `die "$(drain_gate_refusal ...)"` call —
nothing proved that call site was ever consulted. Mutating it to a flat
`die "aborted -- nothing changed"` left the whole suite green, silently
reinstating the exact defect #517 was filed to fix.

Same shape as #521/#526's should_swap/swap_if_built: the decision and the
die() now live together in refuse_drain_gate, which the main flow calls
unconditionally. drain_gate_refusal stays separate and separately tested
for the message logic; four new behavioural tests stub die() to prove
refuse_drain_gate calls it correctly for all four cases, and a fifth
source-text test pins the main flow's call site itself (the only thing
that can catch deleting the call, since sourcing stops before the main
flow runs).
2026-09-12 12:38:16 +07:00
15 changed files with 861 additions and 364 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());
}
}
+169 -9
View File
@@ -42,6 +42,14 @@
# 8. fleetd #492 — a post-restart check counts running fleetd processes and fails the whole run if
# more than one is alive. That is the one thing none of the checks above (healthz 200, jar id,
# the fresh "listening" line) can see: every one of them is satisfied by EITHER daemon.
# 9. fleetd #512 — the ERROR-line count above is blind by construction to the exact failure #493
# is about: an uncaught exception in a shutdown thread never passes through the logger, so it
# never carries an ERROR (or SEVERE) token that any count could see. This script now also
# greps the previous daemon's shutdown window for that exception's real shape, and separately
# asserts that SessionManager's drain-complete line (fleetd #522) is present there — its
# absence is the real signal, because a drain that dies on its first session prints nothing
# else either. Warns loudly; never fails the redeploy, because by the time this is detectable
# the new daemon is already up and healthy.
#
# Usage:
# scripts/redeploy-fleetd.sh # build, confirm, restart, verify
@@ -306,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
@@ -490,6 +500,114 @@ classify_amqp_connection_errors() {
REDEPLOY_UNEXPLAINED_ERRORS=$((REDEPLOY_UNEXPLAINED_ERRORS + pending_inbox + pending_lead_mailbox))
}
# fleetd #512 part 2 — the negative check. #493's failure (an uncaught exception in a shutdown
# thread) never passes through the logger: the JVM's default uncaught-exception handler prints
# straight to stderr, so the line never carries a level, so classify_amqp_connection_errors's
# ERROR/SEVERE token scan is structurally blind to it — measured on two hosts, including one where
# even a syslog PRIORITY filter is blind to it too (fd 1 and fd 2 collapse to one socket there, so
# every uncaught-exception line lands at priority 6/info). The fix is to grep the shape instead of
# the level: `Exception in thread` at the start of a line (the handler's own banner) or
# `NoClassDefFoundError` anywhere in it (the one real instance seen so far, but not the only shape
# this could take). Kept as its own function, never folded into classify_amqp_connection_errors —
# this is not an AMQP concern, and the two must stay independently readable and independently
# testable.
#
# Sets REDEPLOY_UNCAUGHT_EXCEPTION_COUNT (lines matched) and REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE
# (the first matching line, "" if none) so a caller can report both a count and a concrete quote
# without re-reading the file. Pure: reads $1, sets globals, no side effects.
scan_uncaught_exceptions() {
local log_file="$1" line
REDEPLOY_UNCAUGHT_EXCEPTION_COUNT=0
REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE=""
while IFS= read -r line || [ -n "$line" ]; do
case "$line" in
'Exception in thread'*|*NoClassDefFoundError*)
REDEPLOY_UNCAUGHT_EXCEPTION_COUNT=$((REDEPLOY_UNCAUGHT_EXCEPTION_COUNT + 1))
[ -n "$REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" ] || REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE="$line"
;;
esac
done < "$log_file"
}
# fleetd #512 part 2 — the positive check. fleetd #522 added a `log.info` at the very end of
# SessionManager.drainAll's normal path (never in a `finally` — see the ticket discussion for why
# that distinction matters): "drain complete: released=N abandoned=M (still BUSY at the shutdown
# deadline)", printed once, on every successful drain, including the all-zero case. A drain that
# dies partway through never reaches that statement, so the line's ABSENCE is a real signal — unlike
# the ERROR-count check above, this one does not depend on the failure happening to throw.
#
# Sets REDEPLOY_DRAIN_COMPLETE_LINE to the matching line (last one, though drainAll runs at most
# once per shutdown so there should never be more than one) or "" if absent. Pure, same shape as
# scan_uncaught_exceptions above.
find_drain_complete_line() {
local log_file="$1"
REDEPLOY_DRAIN_COMPLETE_LINE="$(grep -F 'drain complete: released=' "$log_file" | tail -1 || true)"
}
# fleetd #512 part 2 — THE TRAP, and the reason this is one function instead of two independent
# checks the caller ORs together. Absence of the drain-complete line has TWO causes that need
# OPPOSITE handling, and a naive "line absent -> the drain died" reading collapses them exactly the
# way this whole ticket exists to stop: the line is emitted by the daemon being STOPPED, which is
# running the OLD jar. Until a redeploy has landed fleetd #522 once, every previous daemon predates
# the line and cannot emit it no matter how cleanly it drained — so on the very first redeploy after
# #522 merged, "absent" means "too old to know how", not "died". Only once BOTH signals — this
# line's absence AND scan_uncaught_exceptions' result — have been read together can the three real
# outcomes be told apart:
#
# complete -> the line is present: the drain finished. Name the counts it reported.
# died -> the line is absent AND an uncaught-exception shape was found: the drain died. Name
# what was found.
# unknown -> the line is absent AND no exception shape either: cannot tell. Say so, and say why
# (predates the line, or failed without throwing) — never worded as a pass or a
# failure, and never reassuring: "ok, no ERROR lines" one level up is the exact mistake
# this ticket exists to fix, and this outcome must not reproduce it.
#
# A fourth case, n/a, covers a cold start or a "loaded but wasn't running" restart: no previous
# daemon was actually stopped THIS run, so there is no shutdown window in $log_file to have an
# opinion about at all — scanning it anyway would read the NEW daemon's own startup lines and could
# misreport "cannot tell" on every clean cold start. had_previous_daemon carries that fact in from
# the caller (it already knows $OLD_PID) rather than this function re-deriving it from log content.
#
# Same shape as swap_if_built/refuse_drain_gate (fleetd #521/#528): the decision (which of the four
# outcomes applies) and the action (which ok/warn line to print, and setting REDEPLOY_DRAIN_STATE
# for the "result" section below to consult) live together in ONE function that the main flow calls
# unconditionally — there is no guard left in the main flow to remove, invert, or bypass
# independently of this function. Never calls die(): #512's own decision is to warn loudly and let
# the redeploy stand, because by the time this is detectable the new daemon is already up and
# healthy and failing here would give the operator nothing to do differently.
report_shutdown_drain() {
local log_file="$1" had_previous_daemon="$2"
REDEPLOY_UNCAUGHT_EXCEPTION_COUNT=0
REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE=""
REDEPLOY_DRAIN_COMPLETE_LINE=""
if [ "$had_previous_daemon" != 1 ]; then
REDEPLOY_DRAIN_STATE="n/a"
ok "no previous daemon was running before this restart — nothing to check for a died shutdown drain"
return 0
fi
find_drain_complete_line "$log_file"
scan_uncaught_exceptions "$log_file"
if [ -n "$REDEPLOY_DRAIN_COMPLETE_LINE" ]; then
REDEPLOY_DRAIN_STATE="complete"
ok "previous daemon's shutdown drain finished: $REDEPLOY_DRAIN_COMPLETE_LINE"
elif [ "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" -gt 0 ]; then
REDEPLOY_DRAIN_STATE="died"
warn "previous daemon's shutdown drain DIED — no drain-complete line, and an uncaught exception"
warn "was found in its shutdown window ($REDEPLOY_UNCAUGHT_EXCEPTION_COUNT line(s)):"
warn " $REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE"
warn "Some sessions from the PREVIOUS daemon may not have been released."
else
REDEPLOY_DRAIN_STATE="unknown"
warn "cannot tell whether the previous daemon's shutdown drain finished — no drain-complete line"
warn "and no uncaught-exception shape either. This is NOT a pass and NOT a failure: it means"
warn "either that daemon predates fleetd #522's drain-complete log line, or its drain failed"
warn "without throwing (hung, or returned early)."
fi
}
# fleetd #517: extracted so the suite can call this decision directly, the same way #510 extracted
# wait_for_daemon_exit so its ordering became checkable. Before this, the only test of the drain-gate
# abort message was a grep of this script's own source for the wording — so mutating the `if` below
@@ -519,6 +637,32 @@ drain_gate_refusal() {
fi
}
# fleetd #528 — drain_gate_refusal above is well tested (four cases, all direct), but nothing made
# the MAIN FLOW's abort actually consult it. Before this, the main flow read
# `die "$(drain_gate_refusal "$DO_BUILD" "$JAR_STAGED")"` directly, and mutating that one line to a
# flat `die "aborted — nothing changed"` left the whole suite at exit 0 with zero FAIL lines and
# byte-identical output to a clean run — every one of drain_gate_refusal's own tests still passed,
# because they call the predicate directly and never touch this call site. That silently reinstated
# the exact defect #517 was filed to fix. Same shape as #521/#526's should_swap/swap_if_built: a
# predicate alone is not enough, because a test proving the predicate is right cannot also prove the
# main flow consults it. So the decision (drain_gate_refusal) and the action (die) now live together
# in ONE function, and the main flow calls it unconditionally instead of building the die() call
# itself — there is no guard left in the main flow to remove, invert, or bypass independently of this
# function. drain_gate_refusal stays separate and separately tested because the message-selection
# logic is worth naming and testing on its own; refuse_drain_gate is the only thing that ever dies.
#
# What the behavioural tests above still cannot pin on their own: deleting the call to this function
# from the main flow altogether — they call refuse_drain_gate directly, never through the main flow,
# because sourcing stops before the main flow ever runs (see the SOURCED guard below). That gap is
# closed the same way swap_if_built's is: test_refuse_drain_gate_call_site_present greps this script
# for the real invocation, the same shape test_swap_ordered_after_wait_and_before_start already uses
# for the swap call. Deliberately NOT written out here as a literal quoted string, so this comment
# itself can never become a second match for that test's needle.
refuse_drain_gate() {
local do_build="$1" staged_path="$2"
die "$(drain_gate_refusal "$do_build" "$staged_path")"
}
# CB-600: sourceable for testing. When this file is SOURCED (not executed) it stops here — nothing
# below runs — so a test harness can `source` it to call check_log_path_matches_plist (or the
# other pure helpers above) against a throwaway plist fixture without ever reaching the mutating
@@ -677,10 +821,11 @@ if [ -n "$OLD_PID" ] && [ "$ASSUME_YES" = 0 ]; then
echo
read -r -p " Fleet drained? type yes to restart: " reply
if [ "$reply" != "yes" ]; then
# fleetd #493 / #517: "nothing changed" would be a lie once a build has run and staged a jar —
# see drain_gate_refusal above for the full decision and why each of its four cases reads the
# way it does.
die "$(drain_gate_refusal "$DO_BUILD" "$JAR_STAGED")"
# fleetd #493 / #517 / #528: "nothing changed" would be a lie once a build has run and staged a
# jar — see drain_gate_refusal above for the full decision and why each of its four cases reads
# the way it does. refuse_drain_gate composes that message AND calls die itself, so this guard
# has nothing left of its own to get wrong beyond whether it calls refuse_drain_gate at all.
refuse_drain_gate "$DO_BUILD" "$JAR_STAGED"
fi
fi
@@ -873,6 +1018,14 @@ trap 'rm -f "$FRESH_LOG"' EXIT
tail -n "+$((RESTART_MARK + 1))" "$OUT" > "$FRESH_LOG" 2>/dev/null || true
classify_amqp_connection_errors "$FRESH_LOG"
# fleetd #512 part 2: the previous daemon's shutdown drain, checked in the same fresh-log region —
# see report_shutdown_drain above for the full decision (four outcomes, one of them a deliberate
# "cannot tell"). HAD_OLD_PID crosses in whether a previous daemon was actually stopped this run;
# see the function's own comment for why that matters.
say "previous daemon's shutdown drain"
HAD_OLD_PID=0; [ -n "$OLD_PID" ] && HAD_OLD_PID=1
report_shutdown_drain "$FRESH_LOG" "$HAD_OLD_PID"
# fleetd #492: checked here, after healthz and the fresh-log check have both had time to run, so a
# supervisor that revives the OLD jar a few seconds late is caught too. Every check above (healthz
# 200, jar id, the fresh 'listening' line) is satisfied by EITHER daemon if two are alive — this is
@@ -882,7 +1035,14 @@ assert_single_daemon "$(running_pid)"
say "result"
ok "pid $NEW_PID, jar $(jar_id)"
if [ "$REDEPLOY_ERROR_COUNT" -eq 0 ]; then
ok "no ERROR lines since restart"
# fleetd #512 item 4: this line must not print when the shutdown-drain check above found the
# previous daemon's drain died, or could not tell — either would make "no ERROR lines" read as a
# clean bill of health it is not (an uncaught exception never carries an ERROR token to begin
# with, so this count alone cannot see that failure). "complete" and "n/a" are the only two
# outcomes report_shutdown_drain sets that mean nothing is wrong there.
if [ "$REDEPLOY_DRAIN_STATE" = "complete" ] || [ "$REDEPLOY_DRAIN_STATE" = "n/a" ]; then
ok "no ERROR lines since restart"
fi
elif [ "$REDEPLOY_UNEXPLAINED_ERRORS" -eq 0 ]; then
ok "$REDEPLOY_RECOVERED_AMQP_ERRORS AMQP connection reset ERROR lines recovered since restart"
else
+274
View File
@@ -521,6 +521,106 @@ test_drain_gate_refusal_no_build_staged_absent() {
assert_equals "aborted — nothing changed" "$result" "no-build+staged-absent refusal wording"
}
# fleetd #528 — the four tests above pin drain_gate_refusal(), and that is ALL they pin: they call
# the predicate directly and never touch the main flow's call site. That was measured to be not
# enough, the same way test_should_swap_true_when_build_ran/test_should_swap_false_when_build_skipped
# were not enough for #521: with the main flow reading `die "$(drain_gate_refusal "$DO_BUILD"
# "$JAR_STAGED")"`, replacing that whole line with a flat `die "aborted — nothing changed"` left this
# suite at exit 0 with zero FAIL lines and byte-identical output to a clean run. Nothing above could
# tell the difference, because none of it calls anything at or above the call site itself.
#
# So these four call refuse_drain_gate() — the function the main flow actually calls, holding the
# composed message and the die() together — with die() stubbed to RECORD whether it was called and
# with what message, instead of exiting the process. That fails if refuse_drain_gate stops consulting
# drain_gate_refusal, mangles what it passes it, or simply never calls die.
#
# What none of these four can catch: deleting the `refuse_drain_gate "$DO_BUILD" "$JAR_STAGED"` line
# from the main flow altogether — see the comment above refuse_drain_gate in redeploy-fleetd.sh for
# why no test in this file can do better than that (sourcing stops before the main flow runs).
DIED_CALLED=0
DIED_MESSAGE=""
stub_die_recorder() {
DIED_CALLED=0
DIED_MESSAGE=""
die() { DIED_CALLED=1; DIED_MESSAGE="$*"; }
}
test_refuse_drain_gate_build_ran_staged_present() {
source "$ROOT/scripts/redeploy-fleetd.sh"
local dir staged
dir="$TMP/refuse-drain-build-staged"; mkdir -p "$dir"
staged="$dir/fleetd-new.jar"
printf 'staged jar bytes' > "$staged"
stub_die_recorder
refuse_drain_gate 1 "$staged"
[ "$DIED_CALLED" = 1 ] \
|| fail "refuse_drain_gate build-ran+staged-present must call die, and did not"
printf '%s' "$DIED_MESSAGE" | grep -qF "$staged" \
|| fail "refuse_drain_gate build-ran+staged-present die message does not name the staged jar"
printf '%s' "$DIED_MESSAGE" | grep -qF 'Rerun WITHOUT --no-build' \
|| fail "refuse_drain_gate build-ran+staged-present die message is missing the rerun instruction"
if printf '%s' "$DIED_MESSAGE" | grep -qF 'nothing changed'; then
fail "refuse_drain_gate build-ran+staged-present must not claim nothing changed — the jar already moved"
fi
source "$ROOT/scripts/redeploy-fleetd.sh"
}
test_refuse_drain_gate_build_ran_staged_absent() {
source "$ROOT/scripts/redeploy-fleetd.sh"
local dir
dir="$TMP/refuse-drain-build-no-staged"; mkdir -p "$dir"
stub_die_recorder
refuse_drain_gate 1 "$dir/fleetd-new.jar"
[ "$DIED_CALLED" = 1 ] \
|| fail "refuse_drain_gate build-ran+staged-absent must call die, and did not"
assert_equals "aborted — nothing changed" "$DIED_MESSAGE" "refuse_drain_gate build-ran+staged-absent die message"
source "$ROOT/scripts/redeploy-fleetd.sh"
}
test_refuse_drain_gate_no_build_staged_present() {
source "$ROOT/scripts/redeploy-fleetd.sh"
local dir staged
dir="$TMP/refuse-drain-no-build-staged"; mkdir -p "$dir"
staged="$dir/fleetd-new.jar"
printf 'leftover staged jar bytes' > "$staged"
stub_die_recorder
refuse_drain_gate 0 "$staged"
[ "$DIED_CALLED" = 1 ] \
|| fail "refuse_drain_gate no-build+staged-present must call die, and did not"
assert_equals "aborted — nothing changed" "$DIED_MESSAGE" "refuse_drain_gate no-build+staged-present die message"
source "$ROOT/scripts/redeploy-fleetd.sh"
}
test_refuse_drain_gate_no_build_staged_absent() {
source "$ROOT/scripts/redeploy-fleetd.sh"
local dir
dir="$TMP/refuse-drain-no-build-no-staged"; mkdir -p "$dir"
stub_die_recorder
refuse_drain_gate 0 "$dir/fleetd-new.jar"
[ "$DIED_CALLED" = 1 ] \
|| fail "refuse_drain_gate no-build+staged-absent must call die, and did not"
assert_equals "aborted — nothing changed" "$DIED_MESSAGE" "refuse_drain_gate no-build+staged-absent die message"
source "$ROOT/scripts/redeploy-fleetd.sh"
}
# fleetd #528 — closes the one gap the four behavioural tests above cannot: they call
# refuse_drain_gate directly, and sourcing stops before the main flow ever runs (the SOURCED guard),
# so none of them can prove the main flow still CALLS refuse_drain_gate at all. Same shape as
# test_swap_ordered_after_wait_and_before_start: a source-text grep for the real call site. This is
# what actually kills the item-1 mutation from the ticket — replacing the main flow's call with a
# flat `die "aborted — nothing changed"` removes this exact needle, where none of the behavioural
# tests above would even notice.
#
# The grep ends `|| true`: this file runs under `set -euo pipefail`, so an ABSENT needle would fail
# the assignment and `set -e` would kill the whole suite before the `[ -n ... ] || fail` guard below
# ever ran — the exact dead-check shape fleetd #528 also flags as a sweep finding (see the PR body).
test_refuse_drain_gate_call_site_present() {
local src="$ROOT/scripts/redeploy-fleetd.sh" call_line
call_line="$(grep -Fn 'refuse_drain_gate "$DO_BUILD" "$JAR_STAGED"' "$src" | head -1 | cut -d: -f1 || true)"
[ -n "$call_line" ] \
|| fail "could not find the main flow's refuse_drain_gate call site in redeploy-fleetd.sh"
}
test_no_errors() {
cat > "$TMP/no-errors.log" <<'LOG'
2026-09-05 12:00:00 INFO fleetd listening
@@ -720,6 +820,164 @@ test_unattributable_quiet_mutation_is_caught() {
printf 'Unattributable mutation: FAIL: cross-unattributable recovered: expected 0, got 2\n'
}
# fleetd #512 part 2 — the negative check (scan_uncaught_exceptions). The heart of this half of the
# ticket: a fixture with the uncaught-exception shape and NO line carrying an ERROR token at all,
# proving the scan finds it without one. A fixture that also carried an ERROR line would pass for
# the wrong reason.
test_scan_uncaught_exceptions_finds_shape_without_error_token() {
cat > "$TMP/scan-died.log" <<'LOG'
2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765
Exception in thread "Thread-0" java.lang.NoClassDefFoundError: reactor/core/Exceptions
at dev.ltms.fleet.session.SessionManager.drainAll(SessionManager.java:1081)
LOG
local error_count
error_count="$(grep -c ' ERROR ' "$TMP/scan-died.log" || true)"
[ "$error_count" = "0" ] \
|| fail "test fixture error: scan-died.log unexpectedly carries an ERROR token"
scan_uncaught_exceptions "$TMP/scan-died.log"
assert_equals 1 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "scan must find the exception without an ERROR token"
printf '%s' "$REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" | grep -qF 'NoClassDefFoundError' \
|| fail "scan did not capture the matching line as the sample"
}
test_scan_uncaught_exceptions_clean_control() {
cat > "$TMP/scan-clean.log" <<'LOG'
2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765
2026-09-12 10:15:05 INFO dev.ltms.fleet.session.SessionManager - drain complete: released=0 abandoned=0 (still BUSY at the shutdown deadline)
LOG
scan_uncaught_exceptions "$TMP/scan-clean.log"
assert_equals 0 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "clean control must find no uncaught exception"
assert_equals "" "$REDEPLOY_UNCAUGHT_EXCEPTION_SAMPLE" "clean control sample must be empty"
}
# fleetd #512 part 2 — the positive check (find_drain_complete_line). Both halves of #522's line:
# present, and absent.
test_find_drain_complete_line_present() {
cat > "$TMP/drain-line-present.log" <<'LOG'
2026-09-12 10:15:05 INFO dev.ltms.fleet.session.SessionManager - drain complete: released=2 abandoned=1 (still BUSY at the shutdown deadline)
LOG
find_drain_complete_line "$TMP/drain-line-present.log"
printf '%s' "$REDEPLOY_DRAIN_COMPLETE_LINE" | grep -qF 'released=2 abandoned=1' \
|| fail "find_drain_complete_line did not capture the present line"
}
test_find_drain_complete_line_absent() {
cat > "$TMP/drain-line-absent.log" <<'LOG'
2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765
LOG
find_drain_complete_line "$TMP/drain-line-absent.log"
assert_equals "" "$REDEPLOY_DRAIN_COMPLETE_LINE" "find_drain_complete_line must report empty when absent"
}
# fleetd #512 part 2 — report_shutdown_drain, the composite decision+action function the main flow
# calls unconditionally (same shape as swap_if_built/refuse_drain_gate, #521/#528). These four cover
# the four outcomes named in the ticket's "trap": complete, died, unknown ("cannot tell" — neither a
# pass nor a failure), and n/a (no previous daemon was actually stopped this run).
#
# Deliberately NOT run inside `$(...)`: report_shutdown_drain sets REDEPLOY_DRAIN_STATE as a global
# side effect that these tests need to read back afterward, and a command substitution forks a
# subshell that global assignment would not survive (the exact trap documented above
# detect_supervisor in redeploy-fleetd.sh, for the same reason). Plain output redirection to a file
# does not fork a subshell, so it is used to capture what was printed instead.
test_report_shutdown_drain_died_without_error_token() {
cat > "$TMP/drain-died.log" <<'LOG'
2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765
2026-09-12 10:15:05 INFO dev.ltms.fleet.Fleetd - shutting down
Exception in thread "Thread-0" java.lang.NoClassDefFoundError: reactor/core/Exceptions
at dev.ltms.fleet.session.SessionManager.drainAll(SessionManager.java:1081)
LOG
local error_count
error_count="$(grep -c ' ERROR ' "$TMP/drain-died.log" || true)"
[ "$error_count" = "0" ] \
|| fail "test fixture error: drain-died.log unexpectedly carries an ERROR token"
report_shutdown_drain "$TMP/drain-died.log" 1 > "$TMP/drain-died-output" 2>&1
assert_equals "died" "$REDEPLOY_DRAIN_STATE" "died fixture must set REDEPLOY_DRAIN_STATE=died"
assert_equals 1 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "died fixture uncaught-exception count"
grep -qF 'NoClassDefFoundError' "$TMP/drain-died-output" \
|| fail "report_shutdown_drain did not report the uncaught-exception shape it found"
grep -qF 'DIED' "$TMP/drain-died-output" \
|| fail "report_shutdown_drain did not report the drain as DIED"
}
test_report_shutdown_drain_complete_control() {
cat > "$TMP/drain-complete.log" <<'LOG'
2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765
2026-09-12 10:15:05 INFO dev.ltms.fleet.Fleetd - shutting down
2026-09-12 10:15:05 INFO dev.ltms.fleet.session.SessionManager - drain complete: released=3 abandoned=0 (still BUSY at the shutdown deadline)
LOG
report_shutdown_drain "$TMP/drain-complete.log" 1 > "$TMP/drain-complete-output" 2>&1
assert_equals "complete" "$REDEPLOY_DRAIN_STATE" "complete-control fixture must set REDEPLOY_DRAIN_STATE=complete"
assert_equals 0 "$REDEPLOY_UNCAUGHT_EXCEPTION_COUNT" "complete-control fixture must find no uncaught exception"
grep -qF 'released=3 abandoned=0' "$TMP/drain-complete-output" \
|| fail "report_shutdown_drain did not report the drain-complete counts"
}
test_report_shutdown_drain_unknown_cannot_tell() {
cat > "$TMP/drain-unknown.log" <<'LOG'
2026-09-12 10:15:00 INFO fleetd listening on 127.0.0.1:8765
2026-09-12 10:15:05 INFO dev.ltms.fleet.Fleetd - shutting down
LOG
report_shutdown_drain "$TMP/drain-unknown.log" 1 > "$TMP/drain-unknown-output" 2>&1
assert_equals "unknown" "$REDEPLOY_DRAIN_STATE" "cannot-tell fixture must set REDEPLOY_DRAIN_STATE=unknown"
grep -qF 'cannot tell' "$TMP/drain-unknown-output" \
|| fail "report_shutdown_drain did not say it could not tell"
if grep -qF ' ok' "$TMP/drain-unknown-output"; then
fail "cannot-tell outcome must not be printed via ok() — it is neither a pass nor a failure"
fi
}
# A cold start (or a restart where nothing was actually stopped) has no previous-daemon shutdown
# window to have an opinion about at all. This fixture's log content looks exactly like a died drain
# — proving the had_previous_daemon=0 gate is actually consulted, not merely documented: without it,
# this would misreport "died" or "unknown" on every clean cold start.
test_report_shutdown_drain_no_previous_daemon_is_na() {
cat > "$TMP/drain-na.log" <<'LOG'
Exception in thread "Thread-0" java.lang.NoClassDefFoundError: reactor/core/Exceptions
LOG
report_shutdown_drain "$TMP/drain-na.log" 0 > "$TMP/drain-na-output" 2>&1
assert_equals "n/a" "$REDEPLOY_DRAIN_STATE" "no-previous-daemon fixture must set REDEPLOY_DRAIN_STATE=n/a even though the log content looks like a died drain"
grep -qF 'nothing to check' "$TMP/drain-na-output" \
|| fail "report_shutdown_drain did not report that there was nothing to check"
}
# fleetd #512 — closes the gap none of the seven tests above can: they call report_shutdown_drain
# directly, and sourcing stops before the main flow ever runs (the SOURCED guard), so none of them
# can prove the main flow still calls it at all. Same shape as test_refuse_drain_gate_call_site_present
# and test_swap_ordered_after_wait_and_before_start: a source-text grep for the real call site, plus
# an ordering check against its neighbours in the verify/result flow.
test_report_shutdown_drain_call_site_present() {
local src="$ROOT/scripts/redeploy-fleetd.sh" call_line
call_line="$(grep -Fn 'report_shutdown_drain "$FRESH_LOG" "$HAD_OLD_PID"' "$src" | head -1 | cut -d: -f1 || true)"
[ -n "$call_line" ] \
|| fail "could not find the main flow's report_shutdown_drain call site in redeploy-fleetd.sh"
}
test_report_shutdown_drain_ordered_after_classify_and_before_result() {
local src="$ROOT/scripts/redeploy-fleetd.sh" classify_line drain_line result_line
classify_line="$(grep -Fn 'classify_amqp_connection_errors "$FRESH_LOG"' "$src" | tail -1 | cut -d: -f1 || true)"
drain_line="$(grep -Fn 'report_shutdown_drain "$FRESH_LOG" "$HAD_OLD_PID"' "$src" | head -1 | cut -d: -f1 || true)"
result_line="$(grep -Fn 'say "result"' "$src" | head -1 | cut -d: -f1 || true)"
[ -n "$classify_line" ] || fail "could not find the classify_amqp_connection_errors call site"
[ -n "$drain_line" ] || fail "could not find the report_shutdown_drain call site"
[ -n "$result_line" ] || fail "could not find the result section"
[ "$drain_line" -gt "$classify_line" ] \
|| fail "report_shutdown_drain (line $drain_line) is not after classify_amqp_connection_errors (line $classify_line)"
[ "$drain_line" -lt "$result_line" ] \
|| fail "report_shutdown_drain (line $drain_line) is not before the result section (line $result_line)"
}
# fleetd #512 item 4 — the summary line must not read as reassurance when the shutdown-drain check
# found something wrong (or could not tell). Sourcing stops before the main flow runs, so this is a
# source-text check like test_drain_gate_abort_message_says_no_no_build above.
test_no_error_lines_message_gated_by_drain_state() {
local src="$ROOT/scripts/redeploy-fleetd.sh" block
block="$(grep -B2 -F 'ok "no ERROR lines since restart"' "$src")"
[ -n "$block" ] || fail "could not find the 'no ERROR lines since restart' line in redeploy-fleetd.sh"
printf '%s' "$block" | grep -qF 'REDEPLOY_DRAIN_STATE' \
|| fail "'no ERROR lines since restart' is not guarded by the shutdown-drain outcome (fleetd #512 item 4)"
}
test_detect_supervisor_launchd_only
test_detect_supervisor_systemd_only
test_detect_supervisor_none
@@ -753,6 +1011,11 @@ test_drain_gate_refusal_build_ran_staged_present
test_drain_gate_refusal_build_ran_staged_absent
test_drain_gate_refusal_no_build_staged_present
test_drain_gate_refusal_no_build_staged_absent
test_refuse_drain_gate_build_ran_staged_present
test_refuse_drain_gate_build_ran_staged_absent
test_refuse_drain_gate_no_build_staged_present
test_refuse_drain_gate_no_build_staged_absent
test_refuse_drain_gate_call_site_present
test_no_errors
test_recovery_patterns_match_source
test_attributed_recovered_connection_error
@@ -764,4 +1027,15 @@ test_other_error_is_unexplained
test_recovery_requirement_mutation_is_caught
test_shared_counter_mutation_is_caught
test_unattributable_quiet_mutation_is_caught
test_scan_uncaught_exceptions_finds_shape_without_error_token
test_scan_uncaught_exceptions_clean_control
test_find_drain_complete_line_present
test_find_drain_complete_line_absent
test_report_shutdown_drain_died_without_error_token
test_report_shutdown_drain_complete_control
test_report_shutdown_drain_unknown_cannot_tell
test_report_shutdown_drain_no_previous_daemon_is_na
test_report_shutdown_drain_call_site_present
test_report_shutdown_drain_ordered_after_classify_and_before_result
test_no_error_lines_message_gated_by_drain_state
printf 'PASS: redeploy log classifier\n'