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

A test pins the shared SessionManager logger to WARN and never restores it, so any later test asserting an INFO line silently sees nothing #525

New Issue
Closed
opened 2026-09-12 06:35:25 +02:00 by ltms · 1 comment
ltms commented 2026-09-12 06:35:25 +02:00
Owner
Copy Link
Copy Source

Found while adjudicating #522 (merged, fleetd #512 part 1). The #522 worker hit this, worked around
it, and reported it. I verified it in the code before filing.

The defect

fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java, in
onTurnFailedIsLoggedAtWarnWithThePriorState:

sessionLog.setLevel(Level.WARN);     // <- sets the level on the SHARED logger
...
} finally {
    sessionLog.detachAppender(appender);   // <- detaches the appender, and nothing else
}

The finally restores the appender. It does not restore the level. sessionLog is the logger
for SessionManager itself, shared by the whole JVM, so once this test has run every later test in
that class — and any other test in the same fork that logs through SessionManager — sees a logger
pinned at WARN.

Verified:

awk '/void onTurnFailedIsLoggedAtWarnWithThePriorState/,/^    }$/' SessionManagerTest.java | grep -n 'setLevel|finally|Level\.'
12:        sessionLog.setLevel(Level.WARN);
24:                    .filter(e -> e.getLevel().equals(Level.WARN))
30:        } finally {

(the finally body, read back)
        } finally {
            sessionLog.detachAppender(appender);
        }

On main before #522: grep -c 'onTurnFailedIsLoggedAtWarnWithThePriorState' → 1, so this is
pre-existing and not something #522 introduced.

What it cost, already

The #522 worker added a test asserting a new log.info line. It passed when run alone and failed —
silently, by seeing no log output at all — when the full class ran. Their words: it "silently ate my
log.info the first time I ran the full class (I only caught it because I ran the whole build, not
just the two new tests in isolation)."

They fixed it for themselves by pinning Level.INFO at the top of each new test and restoring with
sessionLog.setLevel(null) in a finally. That is the right local fix and it is in main now. The
landmine is still there for the next person.

Why this is worth its own ticket rather than a note

This is a new way into the vacuous-test family — a test that stays green when the behaviour is
absent — and the mechanism is not one of the five already recorded:

  1. barrier by hope — a sleep standing in for a wait
  2. a precondition never established, plus a negative assertion
  3. an expectation computed the way the implementation computes it
  4. an instrument shared by two tests that lies identically to both (#507)
  5. a source-text assertion whose text survives its own branch being dead (#517, #521)
  6. a test that leaves a shared instrument mis-set for every test that runs after it ← this one

The distinguishing feature: the damage is not in the test that has the bug. It is in every later
test, and it depends on execution order, so it appears and disappears when tests are reordered, run
alone, or split across forks. An INFO assertion written after this test is vacuous by default — it
cannot see its own subject — and nothing in the failing test's own code is wrong.

It is also the one member of the family that a reviewer of the new test cannot catch by reading the
new test.

The fix

  1. Restore the level in that test's finally: sessionLog.setLevel(previous) where previous is
    captured before the setLevel(Level.WARN) call, or setLevel(null) to fall back to the
    configured level. Do this wherever the pattern appears, not only in the one test named above —
    sweep the file and report every setLevel whose finally does not restore it.
  2. Prefer a shape that cannot be got wrong. A small JUnit extension or an AutoCloseable helper that
    captures the level, attaches the appender, and restores both on close, used with
    try-with-resources, removes the chance of restoring one and forgetting the other. If you add one,
    convert every existing call site to it so there is one way to do this.
  3. Sweep the rest of fleetd/src/test for the same shape: any test that mutates shared static or
    logger state and does not restore all of it. List what you find; fix only the logger-level ones in
    this ticket.

Acceptance

  • mvn -f fleetd/pom.xml clean install exits 0. Report the Tests run / Failures / Errors / Skipped
    line verbatim, and do not pipe the command — a pipe hides a failure behind a zero exit. Redirect to
    a file and echo $? on its own line.
  • A test that proves the leak is closed. The hard part is that this defect is invisible to a test
    written the normal way. One workable shape: a test that asserts the logger's effective level is
    unchanged after onTurnFailedIsLoggedAtWarnWithThePriorState has run, with an explicit ordering
    annotation so it runs after. Another: assert in a teardown hook that the level is back to its
    starting value. Say which you chose and why, and show it failing before your fix.
  • Mutation proof. Re-introduce the leak (drop the level restore), show the proving test going
    red, quote the failing assertion and the exit code, restore, confirm byte-identical with
    shasum -a 256, then a green control run. Prove the mutation applied with two greps using
    different search strings plus a grep -n re-read of the line.
  • The two tests added by #522 must keep passing with their own pinning in place. Do not delete their
    local setLevel/restore as "now redundant" — belt and braces is correct here, and a later change
    to the sweep should not be able to make them vacuous again.

Related

  • #512 / #522 — where this was found.
  • #507 — the other shared-instrument member of the family.
  • #517 / #521 — the source-text member, two instances.
Found while adjudicating #522 (merged, fleetd #512 part 1). The #522 worker hit this, worked around it, and reported it. I verified it in the code before filing. ## The defect `fleetd/src/test/java/dev/ltms/fleet/session/SessionManagerTest.java`, in `onTurnFailedIsLoggedAtWarnWithThePriorState`: ```java sessionLog.setLevel(Level.WARN); // <- sets the level on the SHARED logger ... } finally { sessionLog.detachAppender(appender); // <- detaches the appender, and nothing else } ``` The `finally` restores the appender. It does **not** restore the level. `sessionLog` is the logger for `SessionManager` itself, shared by the whole JVM, so once this test has run every later test in that class — and any other test in the same fork that logs through `SessionManager` — sees a logger pinned at `WARN`. Verified: ``` awk '/void onTurnFailedIsLoggedAtWarnWithThePriorState/,/^ }$/' SessionManagerTest.java | grep -n 'setLevel|finally|Level\.' 12: sessionLog.setLevel(Level.WARN); 24: .filter(e -> e.getLevel().equals(Level.WARN)) 30: } finally { (the finally body, read back) } finally { sessionLog.detachAppender(appender); } ``` On `main` before #522: `grep -c 'onTurnFailedIsLoggedAtWarnWithThePriorState'` → 1, so this is pre-existing and not something #522 introduced. ## What it cost, already The #522 worker added a test asserting a new `log.info` line. It passed when run alone and failed — silently, by seeing no log output at all — when the full class ran. Their words: it "silently ate my `log.info` the first time I ran the full class (I only caught it because I ran the whole build, not just the two new tests in isolation)." They fixed it for themselves by pinning `Level.INFO` at the top of each new test and restoring with `sessionLog.setLevel(null)` in a `finally`. That is the right local fix and it is in `main` now. The landmine is still there for the next person. ## Why this is worth its own ticket rather than a note This is a new way into the vacuous-test family — a test that **stays green when the behaviour is absent** — and the mechanism is not one of the five already recorded: 1. barrier by hope — a `sleep` standing in for a wait 2. a precondition never established, plus a negative assertion 3. an expectation computed the way the implementation computes it 4. an instrument shared by two tests that lies identically to both (#507) 5. a source-text assertion whose text survives its own branch being dead (#517, #521) 6. **a test that leaves a shared instrument mis-set for every test that runs after it** ← this one The distinguishing feature: the damage is not in the test that has the bug. It is in every *later* test, and it depends on execution order, so it appears and disappears when tests are reordered, run alone, or split across forks. An INFO assertion written after this test is vacuous by default — it cannot see its own subject — and nothing in the failing test's own code is wrong. It is also the one member of the family that a reviewer of the new test cannot catch by reading the new test. ## The fix 1. Restore the level in that test's `finally`: `sessionLog.setLevel(previous)` where `previous` is captured before the `setLevel(Level.WARN)` call, or `setLevel(null)` to fall back to the configured level. Do this wherever the pattern appears, not only in the one test named above — sweep the file and report every `setLevel` whose `finally` does not restore it. 2. Prefer a shape that cannot be got wrong. A small JUnit extension or an `AutoCloseable` helper that captures the level, attaches the appender, and restores both on close, used with try-with-resources, removes the chance of restoring one and forgetting the other. If you add one, convert every existing call site to it so there is one way to do this. 3. Sweep the rest of `fleetd/src/test` for the same shape: any test that mutates shared static or logger state and does not restore all of it. List what you find; fix only the logger-level ones in this ticket. ## Acceptance - `mvn -f fleetd/pom.xml clean install` exits 0. Report the `Tests run / Failures / Errors / Skipped` line verbatim, and do not pipe the command — a pipe hides a failure behind a zero exit. Redirect to a file and `echo $?` on its own line. - **A test that proves the leak is closed.** The hard part is that this defect is invisible to a test written the normal way. One workable shape: a test that asserts the logger's effective level is unchanged after `onTurnFailedIsLoggedAtWarnWithThePriorState` has run, with an explicit ordering annotation so it runs after. Another: assert in a teardown hook that the level is back to its starting value. Say which you chose and why, and show it failing before your fix. - **Mutation proof.** Re-introduce the leak (drop the level restore), show the proving test going red, quote the failing assertion and the exit code, restore, confirm byte-identical with `shasum -a 256`, then a green control run. Prove the mutation applied with two greps using *different* search strings plus a `grep -n` re-read of the line. - The two tests added by #522 must keep passing with their own pinning in place. Do not delete their local `setLevel`/restore as "now redundant" — belt and braces is correct here, and a later change to the sweep should not be able to make them vacuous again. ## Related - #512 / #522 — where this was found. - #507 — the other shared-instrument member of the family. - #517 / #521 — the source-text member, two instances.
ltms commented 2026-09-12 07:21:56 +02:00
Author
Owner
Copy Link
Copy Source

Merged as a6415f3 (PR #527). Closing.

Acceptance, as I measured it myself

Verified in my own worktree at the pushed head d8985719ebfd645afb6052279616d9ae3d368d65.

Criterion Result
mvn clean install in fleetd/ BUILD SUCCESS — Tests run: 1699, Failures: 0, Errors: 0, Skipped: 0
SessionManagerTest count 72 (69 before + 2 from #522 + 1 new proving test)
Every level pin in the file is restored yes — all 8 capture sites go through CapturedLog; the only raw setLevel/addAppender left are inside CapturedLog itself and the @BeforeAll/@AfterAll baseline pair
Mutation: CapturedLog.close() detaches the appender but does not restore the level killed — expected: <DEBUG> but was: <WARN>
File byte-identical after the mutation was reverted yes — 0228f78424baa4a1fdd6d372ecc4eaa3380e5dde5103c8cb6a3de4e7a42ee345
Green control after restore 24 + 72 tests, 0 failures
CI run 1773 on d898571 success

One count correction to the PR body: it says "all 7" call sites were converted, but its own breakdown (5 leaks + 1 with no setLevel + 2 already fixed by #522) sums to 8, and the file has 8 — 7 CapturedLog.at and 1 CapturedLog.of. The sweep is complete; only the total was misstated.

What this ticket adds to the vacuous-test family

A seventh member, defined as always by its consequence — the suite stays green when the behaviour is absent: a test that leaves a shared instrument mis-set for every test that runs after it. The test that does the damage passes. The failure appears in a different test, often in a different class, and looks like that other test's bug.

Two experiments on what is actually load-bearing

The PR keeps #522's two explicit Level.INFO pins and describes them as "belt-and-braces — a later change to the sweep must not be able to make those two vacuous again." I measured which part really protects those assertions. Both runs put the two classes in one surefire fork with -Dsurefire.runOrder=reversealphabetical, so WorktreeSessionManagerTest runs before SessionManagerTest.

Experiment 1 — remove both Level.INFO pins, keep the @BeforeAll DEBUG baseline. Passed: 24 + 72 tests, 0 failures. The per-test pin is genuinely redundant.

Experiment 2 — also remove the @BeforeAll DEBUG baseline. mvn exit 1, 3 failures:

AssertionFailedError: … expected: <DEBUG> but was: <WARN>
AssertionFailedError: both released sessions must be counted: no drain-complete INFO logged ==> expected: <true> but was: <false>
AssertionFailedError: both the ready and the busy session are released: no drain-complete INFO logged ==> expected: <true> but was: <false>

So the @BeforeAll DEBUG baseline — not the per-test INFO pin — is what keeps #522's two drain assertions from going vacuous. The PR's comment is right that the pin is redundant and wrong about which thing carries the weight.

Consequence for a future reader: do not delete that @BeforeAll as "only there for the proving test." It protects two other tests. I have not changed the comment's wording on main; this ticket is the record.

The leak this does not fix

The WARN in experiment 2 comes from WorktreeSessionManagerTest.java:267-272, which pins SessionManager's logger to Level.WARN in a finally that only calls detachAppender. That is a cross-class leak on the same shared logger, now proven rather than suspected, and out of this ticket's scope.

A wider ticket follows. My repo survey, narrowed to files where every setLevel call is an unrestored literal pin, found 9 files and 19 pins. An earlier, looser version of that survey said 15 files; that regex missed restores made through a captured variable, so 9 is the number I stand behind. The ticket will recommend sharing this CapturedLog helper instead of repeating the fix nine times.

Merged as `a6415f3` (PR #527). Closing. ## Acceptance, as I measured it myself Verified in my own worktree at the pushed head `d8985719ebfd645afb6052279616d9ae3d368d65`. | Criterion | Result | |---|---| | `mvn clean install` in `fleetd/` | BUILD SUCCESS — `Tests run: 1699, Failures: 0, Errors: 0, Skipped: 0` | | `SessionManagerTest` count | 72 (69 before + 2 from #522 + 1 new proving test) | | Every level pin in the file is restored | yes — all 8 capture sites go through `CapturedLog`; the only raw `setLevel`/`addAppender` left are inside `CapturedLog` itself and the `@BeforeAll`/`@AfterAll` baseline pair | | Mutation: `CapturedLog.close()` detaches the appender but does not restore the level | **killed** — `expected: <DEBUG> but was: <WARN>` | | File byte-identical after the mutation was reverted | yes — `0228f78424baa4a1fdd6d372ecc4eaa3380e5dde5103c8cb6a3de4e7a42ee345` | | Green control after restore | 24 + 72 tests, 0 failures | | CI run 1773 on `d898571` | success | One count correction to the PR body: it says "all 7" call sites were converted, but its own breakdown (5 leaks + 1 with no `setLevel` + 2 already fixed by #522) sums to 8, and the file has 8 — 7 `CapturedLog.at` and 1 `CapturedLog.of`. The sweep is complete; only the total was misstated. ## What this ticket adds to the vacuous-test family A seventh member, defined as always by its consequence — *the suite stays green when the behaviour is absent*: **a test that leaves a shared instrument mis-set for every test that runs after it.** The test that does the damage passes. The failure appears in a different test, often in a different class, and looks like that other test's bug. ## Two experiments on what is actually load-bearing The PR keeps #522's two explicit `Level.INFO` pins and describes them as "belt-and-braces — a later change to the sweep must not be able to make those two vacuous again." I measured which part really protects those assertions. Both runs put the two classes in one surefire fork with `-Dsurefire.runOrder=reversealphabetical`, so `WorktreeSessionManagerTest` runs **before** `SessionManagerTest`. **Experiment 1 — remove both `Level.INFO` pins, keep the `@BeforeAll` DEBUG baseline.** Passed: 24 + 72 tests, 0 failures. The per-test pin is genuinely redundant. **Experiment 2 — also remove the `@BeforeAll` DEBUG baseline.** `mvn` exit 1, 3 failures: ``` AssertionFailedError: … expected: <DEBUG> but was: <WARN> AssertionFailedError: both released sessions must be counted: no drain-complete INFO logged ==> expected: <true> but was: <false> AssertionFailedError: both the ready and the busy session are released: no drain-complete INFO logged ==> expected: <true> but was: <false> ``` So the `@BeforeAll` DEBUG baseline — not the per-test `INFO` pin — is what keeps #522's two drain assertions from going vacuous. The PR's comment is right that the pin is redundant and wrong about which thing carries the weight. **Consequence for a future reader: do not delete that `@BeforeAll` as "only there for the proving test."** It protects two other tests. I have not changed the comment's wording on `main`; this ticket is the record. ## The leak this does not fix The `WARN` in experiment 2 comes from `WorktreeSessionManagerTest.java:267-272`, which pins `SessionManager`'s logger to `Level.WARN` in a `finally` that only calls `detachAppender`. That is a cross-class leak on the same shared logger, now proven rather than suspected, and out of this ticket's scope. A wider ticket follows. My repo survey, narrowed to files where *every* `setLevel` call is an unrestored literal pin, found **9 files and 19 pins**. An earlier, looser version of that survey said 15 files; that regex missed restores made through a captured variable, so 9 is the number I stand behind. The ticket will recommend sharing this `CapturedLog` helper instead of repeating the fix nine times.
ltms closed this issue 2026-09-12 07:22:02 +02:00
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
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
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#525
Delete Branch "%!s()"

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?