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

fleetd #525: restore the logger level, not just the appender, in SessionManagerTest #527

Merged
ltms merged 1 commits from worker/525-logger-level-leak-1b4eb0-6 into main 2026-09-12 07:20:45 +02:00
Conversation 1 Commits 1 Files Changed 1
+132 -100
agent commented 2026-09-12 06:50:06 +02:00
Member
Copy Link
Copy Source

fleetd #525: the shared SessionManager logger's level leaked past setLevel(WARN)

The defect

SessionManagerTest.onTurnFailedIsLoggedAtWarnWithThePriorState's finally block only
called sessionLog.detachAppender(appender). It never restored the level that
sessionLog.setLevel(Level.WARN) had pinned. ch.qos.logback.classic.Logger instances
are cached per class and shared across the whole JVM, so every test that ran after this
one — in this class or any other, in the same surefire fork (this project reuses forks
by default) — saw the SessionManager logger pinned at WARN. PR #522 already hit this
live: its new log.info assertion passed alone and silently saw nothing when the full
class ran, and its local fix (setLevel(null) in finally, per test) is on main
untouched by this change.

Fix — three parts, as scoped

1. Restore the level wherever it's set, in this file. Swept the whole file: found and
fixed 5 leaking setLevel call sites (the reported one plus 4 more, one of them on
MemberRegistry.class rather than SessionManager.class):

  • onTurnFailedIsLoggedAtWarnWithThePriorState (WARN, SessionManager)
  • aSecondArchitectOnAnAlreadyBoundProfileIsHeldAsDevNotArchitectAndWarnsLoudly (WARN, MemberRegistry)
  • releasePreservesWorktreeWhenDirtyCheckThrows (WARN, SessionManager)
  • reapIdleCountsAllThreeSessionsWhenOnlyItsWorktreeRemovalFails (WARN, SessionManager)
  • reapIdleSurvivesOneSessionWhoseLauncherStopFails (WARN, SessionManager)

2. Made the shape hard to get wrong. Added CapturedLog, a private AutoCloseable
that captures a logger's level and attaches a ListAppender together, then restores
both on close(). Converted all 7 addAppender/setLevel call sites in this file to
it (the 5 leaks above, plus the one call with no setLevel at all, plus the 2 sites
#522 already fixed by hand with per-test setLevel(null)). The 2 already-fixed sites
keep their explicit per-test pinning as belt-and-braces, per the ticket — a later change
to the sweep must not be able to make those two vacuous again.

3. Swept wider — report only, nothing else changed. Same shape (mutates a shared
logger's level via setLevel, doesn't restore it in finally/@AfterEach) found
elsewhere in fleetd/src/test:

  • dev/ltms/fleet/FleetdAwaitHerdrTest.java:200-211 — attach()/detach() helpers pin
    Fleetd.class to DEBUG; detach() only detaches.
  • dev/ltms/fleet/FleetdReplyInboxSelectionTest.java:53-65 — same shape, same shared
    Fleetd.class logger, pinned to INFO instead — these two files leak into each other.
  • dev/ltms/fleet/auth/AuditLogTest.java:30-44 — @BeforeEach/@AfterEach pin the
    shared "audit" logger to INFO; @AfterEach only detaches.
  • dev/ltms/fleet/inject/CompletionResolverTest.java:473-499
    (failIsLoggedAtWarnWithTheReason) — pins CompletionResolver.class to WARN;
    finally only detaches.
  • dev/ltms/fleet/inject/InjectorTest.java — 4 tests, same shape, pin Injector.class
    to WARN and never restore: lines 504/522, 543/561, 594/613, 657/673.
  • dev/ltms/fleet/lead/LeadRolloverTest.java:865-876 — attachLog()/detachLog()
    helpers pin LeadRollover.class to DEBUG; detachLog() only detaches.
  • dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java:106-117 —
    attach(Class<?> owner)/detach(...) pin whatever logger class is passed in to
    DEBUG; detach() only detaches.
  • dev/ltms/fleet/session/GitWorktreesTest.java:497-511 — @BeforeEach re-pins
    GitWorktrees.class to WARN before every test (self-heals within the class), but
    several tests (lines 815, 830, 1438, 1455, 1475, 1498, 1686) re-pin it to INFO
    mid-test and neither those tests nor @AfterEach restore it, so the level this class
    leaves behind for the next class in the same fork depends on which test ran last.
  • dev/ltms/fleet/session/WorktreeSessionManagerTest.java:257-291
    (releasePreservesDirtyWorktreeAndLogsWarn) — same shape, on the same shared
    SessionManager.class logger     this PR fixes in SessionManagerTest; pins WARN,
    finally only detaches. Out of this ticket's scope (only SessionManagerTest.java
    logger-level leaks were to be fixed) but worth flagging since it touches the same
    logger.

None of these were changed — report only, per the ticket.

Acceptance

  1. mvn -f fleetd/pom.xml clean install exits 0.
    Tests run: 1699, Failures: 0, Errors: 0, Skipped: 0 — BUILD SUCCESS.
    (1698 on main at 37dcefa + 1 new proving test.)

  2. Proving test. Added
    sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn at @Order(2),
    running right after the fixed onTurnFailedIsLoggedAtWarnWithThePriorState at
    @Order(1) (@TestMethodOrder(MethodOrderer.OrderAnnotation.class) on the class;
    every other, unannotated test keeps running after both, in whatever order it already
    ran in). A class-level @BeforeAll forces the SessionManager logger to a
    distinctive baseline (Level.DEBUG) before any test in the class can touch it, so the
    proving test can tell "restored" apart from "happens to already be WARN because
    WorktreeSessionManagerTest's unfixed leak (see above) left it there" — a real risk,
    since surefire reuses JVM forks by default. @AfterAll puts the pre-class level back.

    Shown failing before the fix: reintroduced the leak (removed
    logger.setLevel(originalLevel); from CapturedLog.close()) and re-ran
    mvn -Dtest=SessionManagerTest test:

    Tests run: 72, Failures: 1, Errors: 0, Skipped: 0
dev.ltms.fleet.session.SessionManagerTest.sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn -- Time elapsed: 0.003 s <<< FAILURE!
org.opentest4j.AssertionFailedError: onTurnFailedIsLoggedAtWarnWithThePriorState pins the shared
SessionManager logger to WARN; its cleanup must restore the level it captured (DEBUG, set by this
class's @BeforeAll) rather than leaving WARN pinned for every test that runs after it ==>
expected: <DEBUG> but was: <WARN>

    exit code 1.

  3. Mutation proof.

    • Mutant applied: dropped logger.setLevel(originalLevel); from CapturedLog.close().
    • grep -c 'MUTATION fleetd #525' → 1 present; grep -c 'logger.setLevel(originalLevel);' → 0 absent (both confirm the mutant, not a no-op).
    • Re-ran: proving test red as quoted above, exit 1.
    • Restored the line, then shasum -a 256 on the file matched the pre-mutation hash
      byte-for-byte (0228f78424baa4a1fdd6d372ecc4eaa3380e5dde5103c8cb6a3de4e7a42ee345).
    • grep -c 'MUTATION fleetd #525' → 0 (mutant gone); grep -c 'logger.setLevel(originalLevel);' → 1 (original back);
      grep -n re-read of the line confirmed logger.setLevel(originalLevel); at its
      original spot.
    • Green control run after restore: Tests run: 72, Failures: 0, Errors: 0, Skipped: 0, exit 0.

  4. #522's per-test pinning kept. drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain
    and drainAllLogsANonZeroAbandonedCountForASessionStillBusyAtTheDeadline still pin
    Level.INFO explicitly per test (now via CapturedLog.at(SessionManager.class, Level.INFO) instead of the hand-rolled setLevel/setLevel(null) pair), as
    belt-and-braces on top of the class-wide fix.

Files changed

  • fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java (only file touched)
## fleetd #525: the shared SessionManager logger's level leaked past setLevel(WARN) ### The defect `SessionManagerTest.onTurnFailedIsLoggedAtWarnWithThePriorState`'s `finally` block only called `sessionLog.detachAppender(appender)`. It never restored the level that `sessionLog.setLevel(Level.WARN)` had pinned. `ch.qos.logback.classic.Logger` instances are cached per class and shared across the whole JVM, so every test that ran after this one — in this class or any other, in the same surefire fork (this project reuses forks by default) — saw the `SessionManager` logger pinned at WARN. PR #522 already hit this live: its new `log.info` assertion passed alone and silently saw nothing when the full class ran, and its local fix (`setLevel(null)` in `finally`, per test) is on `main` untouched by this change. ### Fix — three parts, as scoped **1. Restore the level wherever it's set, in this file.** Swept the whole file: found and fixed 5 leaking `setLevel` call sites (the reported one plus 4 more, one of them on `MemberRegistry.class` rather than `SessionManager.class`): - `onTurnFailedIsLoggedAtWarnWithThePriorState` (WARN, `SessionManager`) - `aSecondArchitectOnAnAlreadyBoundProfileIsHeldAsDevNotArchitectAndWarnsLoudly` (WARN, `MemberRegistry`) - `releasePreservesWorktreeWhenDirtyCheckThrows` (WARN, `SessionManager`) - `reapIdleCountsAllThreeSessionsWhenOnlyItsWorktreeRemovalFails` (WARN, `SessionManager`) - `reapIdleSurvivesOneSessionWhoseLauncherStopFails` (WARN, `SessionManager`) **2. Made the shape hard to get wrong.** Added `CapturedLog`, a private `AutoCloseable` that captures a logger's level and attaches a `ListAppender` together, then restores *both* on `close()`. Converted all 7 `addAppender`/`setLevel` call sites in this file to it (the 5 leaks above, plus the one call with no `setLevel` at all, plus the 2 sites #522 already fixed by hand with per-test `setLevel(null)`). The 2 already-fixed sites keep their explicit per-test pinning as belt-and-braces, per the ticket — a later change to the sweep must not be able to make those two vacuous again. **3. Swept wider — report only, nothing else changed.** Same shape (mutates a shared logger's level via `setLevel`, doesn't restore it in `finally`/`@AfterEach`) found elsewhere in `fleetd/src/test`: - `dev/ltms/fleet/FleetdAwaitHerdrTest.java:200-211` — `attach()`/`detach()` helpers pin `Fleetd.class` to DEBUG; `detach()` only detaches. - `dev/ltms/fleet/FleetdReplyInboxSelectionTest.java:53-65` — same shape, same shared `Fleetd.class` logger, pinned to INFO instead — these two files leak into each other. - `dev/ltms/fleet/auth/AuditLogTest.java:30-44` — `@BeforeEach`/`@AfterEach` pin the shared `"audit"` logger to INFO; `@AfterEach` only detaches. - `dev/ltms/fleet/inject/CompletionResolverTest.java:473-499` (`failIsLoggedAtWarnWithTheReason`) — pins `CompletionResolver.class` to WARN; `finally` only detaches. - `dev/ltms/fleet/inject/InjectorTest.java` — 4 tests, same shape, pin `Injector.class` to WARN and never restore: lines 504/522, 543/561, 594/613, 657/673. - `dev/ltms/fleet/lead/LeadRolloverTest.java:865-876` — `attachLog()`/`detachLog()` helpers pin `LeadRollover.class` to DEBUG; `detachLog()` only detaches. - `dev/ltms/fleet/msg/AmqpConnectionFailureLoggerTest.java:106-117` — `attach(Class<?> owner)`/`detach(...)` pin whatever logger class is passed in to DEBUG; `detach()` only detaches. - `dev/ltms/fleet/session/GitWorktreesTest.java:497-511` — `@BeforeEach` re-pins `GitWorktrees.class` to WARN before every test (self-heals within the class), but several tests (lines 815, 830, 1438, 1455, 1475, 1498, 1686) re-pin it to INFO mid-test and neither those tests nor `@AfterEach` restore it, so the level this class leaves behind for the next class in the same fork depends on which test ran last. - `dev/ltms/fleet/session/WorktreeSessionManagerTest.java:257-291` (`releasePreservesDirtyWorktreeAndLogsWarn`) — same shape, on the **same shared `SessionManager.class` logger** this PR fixes in `SessionManagerTest`; pins WARN, `finally` only detaches. Out of this ticket's scope (only `SessionManagerTest.java` logger-level leaks were to be fixed) but worth flagging since it touches the same logger. None of these were changed — report only, per the ticket. ### Acceptance 1. **`mvn -f fleetd/pom.xml clean install` exits 0.** `Tests run: 1699, Failures: 0, Errors: 0, Skipped: 0` — `BUILD SUCCESS`. (1698 on `main` at `37dcefa` + 1 new proving test.) 2. **Proving test.** Added `sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn` at `@Order(2)`, running right after the fixed `onTurnFailedIsLoggedAtWarnWithThePriorState` at `@Order(1)` (`@TestMethodOrder(MethodOrderer.OrderAnnotation.class)` on the class; every other, unannotated test keeps running after both, in whatever order it already ran in). A class-level `@BeforeAll` forces the `SessionManager` logger to a distinctive baseline (`Level.DEBUG`) before any test in the class can touch it, so the proving test can tell "restored" apart from "happens to already be WARN because `WorktreeSessionManagerTest`'s unfixed leak (see above) left it there" — a real risk, since surefire reuses JVM forks by default. `@AfterAll` puts the pre-class level back. **Shown failing before the fix**: reintroduced the leak (removed `logger.setLevel(originalLevel);` from `CapturedLog.close()`) and re-ran `mvn -Dtest=SessionManagerTest test`: ``` Tests run: 72, Failures: 1, Errors: 0, Skipped: 0 dev.ltms.fleet.session.SessionManagerTest.sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn -- Time elapsed: 0.003 s <<< FAILURE! org.opentest4j.AssertionFailedError: onTurnFailedIsLoggedAtWarnWithThePriorState pins the shared SessionManager logger to WARN; its cleanup must restore the level it captured (DEBUG, set by this class's @BeforeAll) rather than leaving WARN pinned for every test that runs after it ==> expected: <DEBUG> but was: <WARN> ``` exit code 1. 3. **Mutation proof.** - Mutant applied: dropped `logger.setLevel(originalLevel);` from `CapturedLog.close()`. - `grep -c 'MUTATION fleetd #525'` → 1 present; `grep -c 'logger.setLevel(originalLevel);'` → 0 absent (both confirm the mutant, not a no-op). - Re-ran: proving test red as quoted above, exit 1. - Restored the line, then `shasum -a 256` on the file matched the pre-mutation hash byte-for-byte (`0228f78424baa4a1fdd6d372ecc4eaa3380e5dde5103c8cb6a3de4e7a42ee345`). - `grep -c 'MUTATION fleetd #525'` → 0 (mutant gone); `grep -c 'logger.setLevel(originalLevel);'` → 1 (original back); `grep -n` re-read of the line confirmed `logger.setLevel(originalLevel);` at its original spot. - Green control run after restore: `Tests run: 72, Failures: 0, Errors: 0, Skipped: 0`, exit 0. 4. **#522's per-test pinning kept.** `drainAllLogsACompletionLineWithTheRealCountsOnACleanDrain` and `drainAllLogsANonZeroAbandonedCountForASessionStillBusyAtTheDeadline` still pin `Level.INFO` explicitly per test (now via `CapturedLog.at(SessionManager.class, Level.INFO)` instead of the hand-rolled `setLevel`/`setLevel(null)` pair), as belt-and-braces on top of the class-wide fix. ### Files changed - `fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java` (only file touched)
agent added 1 commit 2026-09-12 06:50:06 +02:00
fleetd #525: restore the logger level, not just the appender, in SessionManagerTest
CI / contract (pull_request) Successful in 44s
Details
CI / build (pull_request) Successful in 1m53s
Details
d8985719eb 
The finally block in onTurnFailedIsLoggedAtWarnWithThePriorState (and four other
tests in this file) called setLevel(Level.WARN) on the shared SessionManager
logger (one test used MemberRegistry.class) but only detached the appender in
finally, never restoring the level. Since logback Logger instances are cached
per class and shared across the whole JVM, the pinned level leaked into every
test that ran after it.

Add CapturedLog, a small AutoCloseable that captures a logger's level and
appender together and restores both on close via try-with-resources, so this
shape cannot be half-fixed again. Convert all 7 addAppender/setLevel call
sites in this file to it, including the 2 sites #522 already fixed locally
(kept per-test pinning as belt-and-braces).

Add a proving test (sharedSessionManagerLoggerLevelIsRestoredAfterOnTurnFailedPinsWarn,
@Order(2), running right after the fixed test at @Order(1)) that fails before
this fix and passes after it. Verified with a mutation: dropping the level
restore in CapturedLog.close() turns the proving test red with
'expected: <DEBUG> but was: <WARN>'; restoring is byte-identical to the
pre-mutation file (sha256 matched) and the suite goes green again.

mvn -f fleetd/pom.xml clean install: Tests run: 1699, Failures: 0, Errors: 0,
Skipped: 0. BUILD SUCCESS.
ltms merged commit a6415f3e52 into main 2026-09-12 07:20:45 +02:00
ltms commented 2026-09-12 07:20:59 +02:00
Owner
Copy Link
Copy Source

Correction to my own merge message: its first paragraph garbled the test file's hash into 0228f78424boa..., which is not a hash. I then made it worse by retyping from memory in the first version of this comment instead of re-running the command.

Measured, at commit d8985719ebfd645afb6052279616d9ae3d368d65:

$ shasum -a 256 fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java
0228f78424baa4a1fdd6d372ecc4eaa3380e5dde5103c8cb6a3de4e7a42ee345

That matches the value the PR body records in its section 3.

Nothing about the acceptance result changes. The hash was only used to confirm the file was byte-identical before and after the mutation experiments, and that check passed: the mutation applied, it killed the new proving test with expected: <DEBUG> but was: <WARN>, and the restore returned the file to these exact bytes before the green control run.

Correction to my own merge message: its first paragraph garbled the test file's hash into `0228f78424boa...`, which is not a hash. I then made it worse by retyping from memory in the first version of this comment instead of re-running the command. Measured, at commit `d8985719ebfd645afb6052279616d9ae3d368d65`: ``` $ shasum -a 256 fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java 0228f78424baa4a1fdd6d372ecc4eaa3380e5dde5103c8cb6a3de4e7a42ee345 ``` That matches the value the PR body records in its section 3. Nothing about the acceptance result changes. The hash was only used to confirm the file was byte-identical before and after the mutation experiments, and that check passed: the mutation applied, it killed the new proving test with `expected: <DEBUG> but was: <WARN>`, and the restore returned the file to these exact bytes before the green control run.
Sign in to join this conversation.
Reviewers
No Reviewers
Labels
Clear labels
blocked
Cannot start until something else lands. The body says what.
 needs-live-proof
Merged and green, but never shown working on the running daemon. Not the same as done.
 ready-to-delegate
Scope, files and acceptance criteria are written. A worker can be briefed from the body alone.
 silent-default
A feature that compiles, passes tests, and ships turned off. Nine recurrences and counting.
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
agent kevin ltms
No Assignees
2 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#527
Delete Branch "worker/525-logger-level-leak-1b4eb0-6"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?