MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge races the push loop's 300ms tick — reproduced on both hosts, under load #477
Open
opened 2026-09-10 15:48:57 +02:00 by ltms
·
2 comments
No Branch/Tag Specified
main
worker/fleetd-612-unita-87807e-1
worker/612-b3-mcpwirings-da2b58-3
worker/612-b2-cb185-176d3a-2
worker/612-b1-completion-457459-1
worker/612-agaps-73a926-2
worker/608-sleeps-3a64ff-3
worker/621-b4520b-1
worker/618-b83894-2
worker/fleetd-615-e05481-5
worker/lead-autocompact-5f1ab2-3
worker/fleetd-613-f85deb-3
worker/fleetd-608-flaky-nudge-test-d0c2d1-3
worker/lead-context-gauge-ad404f-1
worker/gauge-wiring-9158c1-4
worker/redeploy-slowstart-ead0e5-5
worker/charter-bytes-13668c-6
worker/rollover-outcome-291483-2
worker/589-f64303-2
worker/593-1a8025-5
worker/589-fcd2aa-1
worker/568-9fdaa2-3
worker/571-attempted-outcome-5739f7-2
worker/581-completionresolver-cas-sites-0542b7-6
worker/562-loop-health-wiring-test-99611c-5
worker/562-surface-loop-health-7df5cc-4
worker/575-waiter-cleanup-sites-62ad80-1
worker/572-answer-lock-release-46a9ae-5
worker/567-probe-channel-leak-a38fc5-6
worker/551-record-before-send-7cbf56-1
worker/561-listener-fanout-survives-a-throw-61d538-2
worker/555-redeploy-main-flow-seam-65c2f5-2
worker/556-injector-owns-registration-e027a5-1
worker/552-post-restart-mktemp-abort-bc2672-4
worker/553-onstatus-completion-leak-0da881-2
worker/550-shasum-linux-196132-1
worker/538-loop-dies-on-error-4a5eeb-6
worker/426-health-coverage-ef1fd4-4
worker/504-failed-reported-clean-3cfd66-3
worker/537-capturedlog-close-e4c437-2
worker/459-broken-link-targets-cadc17-5
worker/535-appender-leak-fe74c1-1
worker/512-part2-shutdown-detection-434701-9
worker/529-logger-level-sweep-2a5533-8
worker/528-drain-gate-call-site-5de83d-7
charter/forge-mcp-vs-token
worker/521-swap-guard-unpinned-28e931-5
worker/519-probe-test-harness-d25ab8-4
worker/525-logger-level-leak-1b4eb0-6
worker/518-fleetmcp-resolver-wiring-8ef96c-1
worker/512-drain-complete-line-7edd71-3
worker/517-abort-branch-and-jar-id-41b641-2
worker/500-9e52c9-3
worker/509-4912f4-2
worker/511-9a4b23-1
worker/493-479f45-2
worker/505-03f8b2-1
worker/492-followup-detect-unclear
worker/501-a31fa0-7
worker/498-451d1c-5
worker/494-1015ce-2
worker/492-209647-1
worker/489-001902-2
worker/480-relative-handover-path-906323-1
worker/480-b-handover-skill-45bf1f-5
worker/474-followup-source-pin-f54a55-17
worker/474-charter-check-on-reload-f54a55-17
worker/466-quarantine-repeatcount-report
worker/393-opencode-skill-seeding-71854b-13
worker/469-canonical-tool-names-2a472a-16
worker/466-quarantine-escalation-5ae9c1-15
worker/446-hot-exhausted-pattern-0af580-6
worker/464-charter-tool-name-guard-a85635-12
worker/463-listfleet-default-fails-open-f1c76c-11
worker/458-invariant-5-by-purpose-862f9a-10
worker/439-coordinator-row-gate-bc032a-8
worker/449-herdr-protocol-576015-4
worker/450-abstract-spawn-599e1c-5
worker/437-ack-refuses-177d91-1
worker/444-placement-window-feb56a-2
worker/440-helddurable-derived-d462d7-13
worker/425-rework-placement-resolve-c58ba1-9
worker/421-lead-peek-held-msgs-cdbad2-10
worker/435-fixed-policy-cap-fe11de-12
worker/422-gate-state-observability-9e79d6-11
worker/431-memberregistry-live-readers-cdbad2-10
worker/424-architect-slot-hot-038b41-7
worker/422-model-gate-spawn-c29f48-6
worker/425-default-profile-live-f55534-8
worker/415-coverage-wording-2cbf9c-5
worker/416-3ad1da-1
worker/418-588283-3
worker/deterministic-stamp-race-409-3cb7b6-10
worker/armed-reads-live-config-404-ed931f-9
worker/reply-peer-refusal-391-5a34bd-7
worker/models-allowlist-aa9e9b-3
worker/ttl-stamp-race-399-f1122f-8
worker/scrub-receipt-400-316b3e-5
worker/exhaustion-detection-395-105105-6
worker/scrub-abort-394-316b3e-5
fix/scrub-uid-abort
worker/task-scrub-517574-2
worker/t386-clock-bd5b78-4
worker/t384-scrub-813790-5
worker/t381-cc-748314-2
worker/t373-336973-2
worker/t365-3920c5-3
worker/t358-6e989b-1
worker/t355-8b321c-1
worker/fleetd-369-hermetic-git-tests-e8b19a-3
worker/fleetd-368-stale-lead-binding-f5682e-2
worker/fleetd-360-deploy-units-0d3793-1
worker/359-dead-lead-tabs-f1253b-4
worker/362-worktree-skills-c03e51-3
worker/361-coord-visibility-655144-1
362-plugin-visibility-and-drift
worker/errscan-bed2ca-2
worker/amqp-log-identity-bed2ca-2
worker/withdefaults-guard-561704
worker/sleepguard-82076d-1
worker/fd334-9ee1b6-5
worker/fd348-f1ab27-4
worker/fd335-a71c35-1
worker/fd342-174a17-2
worker/fd345-490d0f-3
worker/fleetd-337-5ec7d4-21
worker/fleetd-341-af5a6b-24
worker/fleetd-339-5ca0a2-23
worker/fleetd-338-83a4a1-22
worker/fleetd-333-281f46-18
worker/fleetd-329-11bdbb-16
worker/fleetd-330-2770fb-17
worker/fix-326-50506e-15
worker/fix-324-3e9bbf-14
worker/fix-323-b8287d-13
worker/fix-316b-bd0860-11
worker/fix-318-76ca36-9
worker/fix-317-486aec-8
worker/fix-315-ce47c5-6
worker/fix-307-275890-6
worker/fix-308-b4f664-7
worker/fix-309-ec3939-8
worker/fix-310-7a3974-9
worker/fix-302-52ad0e-9
worker/fix-298-ce1acb-8
worker/fix-297-66bd11-7
worker/fix-296-104622-6
worker/fix-293-bare-closetab-eb22b5-3
worker/fix-280-gone-ask-lapse-bca98e-2
worker/fix-290-reapidle-guard-coverage-9b0dd1-1
worker/fix-285-trust-seed-8f3565-10
worker/fix-284-backend-error-seat-85912c-11
worker/fix-282-chained-ask-e6d0bb-8
worker/fix-283-teardown-leaks-f40dfa-9
worker/fix-281-pin-handler-actions-4921ac-7
worker/audit-rendezvous-lifecycle-d072ae-2
worker/audit-health-placement-1a2476-6
worker/audit-teardown-exits-e207a5-3
worker/audit-launcher-asymmetry-27e370-4
worker/audit-rest-authz-6ca53c-5
worker/investigate-275-abandon-asking-fdef52-8
worker/fix-274-worktree-leak-b0095d-7
worker/fix-273-exhausted-pattern-9665b5-6
worker/fleetd-267-model-check-bd8068-1
worker/fleetd-131-archunit-18b834-7
worker/fleetd-266-sshagent-rename-a014ff-6
worker/fleetd-184-uid-claim-8e1f31-4
worker/fleetd-184-warn-b381ee-10
worker/fleetd-184-docs-be1d12-9
worker/fleetd-257-9bf010-7
worker/fleetd-103-23a113-6
worker/fleetd-247-342356-5
worker/fleetd-116-04dea8-4
worker/fleetd-252-a830e0-3
worker/fleetd-111-7e8673-9
worker/fleetd-155c-f8ef4b-8
worker/fleetd-176-b928ca-3
worker/fleetd-249-7a7878-2
worker/cb248-composition-root-b-9acdf7-15
worker/cb148-envrc-default-fa6c82-12
worker/cb201-unit5-wiring-6c12e6-8
worker/cb241-fallback-echo-1175e9-11
worker/cb149-trust-dialog-2392a5-9
worker/cb134-148-overlay-visible-c9b986-10
worker/cb234-session-id-keyed-04e1fc-1
worker/cb201-unit3-nudge-abdf5c-6
worker/cb201-unit2-policy-c1102c-5
worker/cb201-unit4-outcome-a13bfa-7
worker/cb201-unit1-classifier-91b9b1-4
worker/cb201-227-refine-831980-3
worker/cb175-model-readback-0f085f-1
worker/cb222-charter-tmpdir-17f013-1
worker/cb226-architect-slot-race-cd3aa8-3
worker/cb224-worktree-root-group-024523-2
worker/cb-123-role-demotion-c600f7-2
worker/cb-219-opencode-roots-1f677e-1
worker/cb214-claude-session-id-b9eab4-4
worker/cb213-zdotdir-wrong-process-dd6de4-3
worker/cb211-exhaustion-classification-9546e0-2
worker/cb137-ambiguous-task-4df3d8-4
worker/cb209-agentsessionid-4dfdb6-2
worker/cb185-hostenvnames-2692b5-3
worker/cb206-opencode-sqlite-128718-2
worker/cb185-worktree-group-fc0c99-1
worker/cb-137-ask-ticket-e7760c-2
worker/cb-172-broker-uri-d36ae4-4
worker/cb-175-model-readback-76ead6-3
worker/cb-161-pane-ancestry-293510-1
worker/cb-164-rebase-885863-8
worker/cb-164-empty-scrape-false-success-1a80af-3
fix/cb-197-ticket-ttl-from-completion
worker/cb-189-remote-url-coverage-4692f3-1
worker/cb-185-blockers-027756-4
worker/cb-192-gap-log-11b631-2
worker/cb-633-fix-5f4396-3
worker/cb185-router-d6436d-3
worker/cb185-router-routing-gaps-9e9d33-3
worker/cb185-paneids-992586-2
worker/cb-633-allow-list-union-ed374b-1
worker/cb-157-credential-in-remote-url-496e44-2
worker/cb-641-health-herdr-evidence-8f1f54-6
worker/cb-640-health-msg-evidence-99c9cd-1
worker/cb-642-fleets-status-skill-bbbc40-5
cb-634-ide-mcp
worker/lead-comms-wiring-c014b9-7
worker/lead-mailbox-c19577-6
worker/autocompact-window-82bc2f-5
worker/cb-634-probe-18056f-4
worker/cb635-broker-urienv
worker/cb-632-config-retry-8e0efa-7
lead/cb-622e-claude-md
lead/cb-622-followup
worker/cb-622a-165dff-1
lead/cb-622d-opencode-mount
worker/cb-622b-717c67-2
worker/cb-622c-ab7759-3
worker/cb-617b2-20ca4b-3
worker/cb-617a-5c2f4a-1
worker/cb596-4e49ef-3
worker/cb586-10500c-1
worker/cb-606-b9343a-25
worker/cb604-1445f8-24
worker/cb582-477374-21
worker/cb584-8c2281-22
worker/cb600-e6b9a9-20
worker/cb602-ce257f-19
worker/cb601-b42837-18
worker/cb598-6c7ba7-17
worker/cb599-740fe4-16
worker/cb597-282224-15
worker/cb590fix-185e9a-10
worker/cb528-recovery-race
worker/cb594-96bead-8
worker/cb590-916766-2
worker/cb527-997d99-3
worker/cb592-env-leak-3cbf9c-1
worker/cb588-async-ticket-nudge-3218f7-5
worker/cb578b-9dcb13-6
worker/cb581-d24826-5
worker/m2-u5-ef8c42-15
worker/cb578a-516499-2
worker/cb576-01a04b-17
worker/cb579-lead-tab-acba06-20
worker/cb580-terminal-health-ed6058-21
worker/cb577-f36fdc-18
worker/cb573b-3db06f-16
worker/cb568c-f36fdc-18
worker/cb568-drop-cause-c3ac1c
worker/cb575-cancelled-notification-c3ac1c
worker/m4-sol-a2cbec-3
worker/cb574-async-ask-c3ac1c
worker/cb573-health-model-8ca857-14
worker/cb572-unknown-target-7f2e35-13
worker/u4-700706-9
worker/u3-b9fcb6-6
worker/u2-ef5b68-4
worker/u1-469dce-1-clean
worker/u1-469dce-1
worker/cb-564-health-events-70cf7e-2
worker/cb-565-recycle-drops-role-98e58f-3
worker/cb-563-missing-reply-df2866-1
worker/cb-562-readiness-gate-silent-6c23c9-3
worker/cb-560-architect-presence-da8155-1
worker/cb-561-architect-silent-off-a71cab-2
worker/cb-548-bind-architect-slot-fe1b8c-1
worker/parity-overlay-settings-5fb711-1
secrets-central-store
cb-559-hot-key-correction
cb-557-fleet-role-pools
worker/cb-553-maxload-explicit-spawn-305ee3-6
worker/cb-551-idle-lead-heartbeat-f1633c-1
worker/cb-544-drain-preserves-worktree-925fad-3
worker/cb-552-docs-sync-1cb9cf-4
worker/cb-548-rendezvous-guard-rebased
worker/cb-548-rendezvous-guard-116b53-10
worker/cb-548-authz-v2-586df6-8
worker/cb-548-authz-264363-5
salvage/cb-528b-codex-home
salvage/cb-528a-codex-launcher
CB-518-primary-flow
feature/peer-launcher-spi
cb-103-injector
v1.1.0
v1.0.0
Labels
Clear labels
blocked
needs-live-proof
ready-to-delegate
silent-default
Cannot start until something else lands. The body says what.
Merged and green, but never shown working on the running daemon. Not the same as done.
Scope, files and acceptance criteria are written. A worker can be briefed from the body alone.
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
Notifications
Due Date
No due date set.
Dependencies
No dependencies set.
Reference: fleet/fleetd#477
Reference in New Issue
Block a user
Blocking a user prevents them from interacting with repositories, such as opening or commenting on pull requests or issues. Learn more about blocking a user.
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?
Found by CI, on a commit I had already reported as green
CI run 1711 failed on
mainat5ba69c9— the #393 merge. My own full build on that commit was 1618 green withBUILD SUCCESS, and I reported it done without reading the runner.It is a flake, not a regression. The two pushes after it,
25ba7f1and4466ee0, are supersets of the same code and both went green (runs 1713 and 1714). A single red with no later green would prove nothing either way; two later greens on more code is what makes this a race rather than a break.Reproduced on macOS, which #399 never was
This matters, because the last
MessageServiceTestrace (#399) failed only on the Linux runner and I could never make it fail here. This one I can.Harness proof first — the selector alone, no mutation, must report exactly one test:
Then 20 runs of
mvn -B -Dtest='MessageServiceTest#anAlreadyCollectedTicketProducesNoNudge' -Dsurefire.failIfNoSpecifiedTests=false teston treefbb9b58:Identical assertion and message to CI's.
The failure is load-correlated, and the elapsed times show it. Runs 1 to 14 all took 0.605s to 0.676s and all passed. Run 15 failed. Runs 16 and 17 took 1.230s and 1.200s — roughly double — then the machine quietened and runs 18 to 20 came back to 0.631s, 0.646s, 0.636s and passed.
I did not plan that load. A delegated worker started a full
mvnbuild on the same machine partway through my loop;sysctl -n vm.loadavgread{ 28.72 11.76 6.32 }during the slow window against{ 3.16 2.74 2.84 }at the start. So the reproduction recipe is: run this test while the machine is busy. One in twenty at 28 load, zero in fourteen at 3.The mechanism
This is my reading of the code, supported by the load correlation, not a separately measured cause.
MessageServiceTest.java:1637wires the push loop with a 300 ms backoff and says so in its own comment:The test then resolves the ticket, calls
awaitTicketPhaseOn(..., Phase.DONE), sleeps 400 ms and asserts no nudge was sent. The poll insideawaitTicketPhaseOnis what marks the ticket collected —MessageService.java:1301callspushLoop.ticketCollected(ticket).So the test depends on winning a race against a real 300 ms scheduled tick, and it establishes no ordering to make that certain. Under load the poll can land after the tick. The tick then finds an uncollected ticket, sends the nudge it is designed to send, and the assertion fails. Nothing is wrong with the production behaviour in that ordering — the lead simply had not polled yet when the tick ran.
This is the same class of defect as #399, with a different pair of steps: a test that must be ordered after an event, ordered instead by hoping a timer has not fired yet. #399's version was
Phase.DONEpublished before thecompletedNanosstamp; this one is a wall-clock window against the push loop's own scheduler.The small real consequence, so it is not overstated
In production the same ordering means a lead can get one nudge naming a ticket it is about to collect. That is a redundant nudge, not a lost or duplicated report, and the per-ticket reminder cap already bounds it. So this ticket is about the test. Do not "fix" it by changing when
ticketCollectedis called.Scope
awaitCompletionStamped(:2092) andawaitPendingQuestionPublishedspin on a package-private state accessor with a bounded deadline and a named failure message. The equivalent here is a seam that reports whether the push loop has been told the ticket is collected — then advance or sleep only after that is true.severalAsyncTicketsFinishingTogetherProduceOneCoalescedNudge(:1654) also useswireWithPushLoop(1, 300)with the comment "wide backoff: both tickets land before the tick fires", and deliberately avoids polling. Say whether it has the same hole, the mirror-image hole, or none. #399's ticket asked the same question about its sibling and the answer was worth having.Thread.sleepcalls inMessageServiceTestare load-bearing barriers rather than settle-time, and list them. There are 20 in the file. Do not rewrite them all in this ticket — the list is the deliverable, so a later ticket can be scoped from a count rather than a guess.Acceptance criteria
Tests run: 1. A cell that runs zero tests is void and reads as a pass.vm.loadavgfrom during the run. Report the elapsed times, or at least the minimum and maximum — they are the instrument that shows the load actually arrived.Filed after CI caught a red on a commit I had already verified locally and reported. The lesson is mine, not the code's: my own green build is one host at one load level, which is one data point.
This ticket and #489 are the same defect family. Naming it, with the bar for calling it a pattern not yet met.
The fleet01 lead gave me a definition while reviewing #490, and was careful to say it is theirs and not a reading of this ticket — their fetch window ends at #470, so #477 postdates their cache and everything they know about it came from my own messages. Their words: "if I hand you my framing on #477, you get your own description back with a second name on it, and it will read as corroboration. It is not." So the judgement below is mine from this ticket's code, and the definition is theirs.
This ticket fits, via the first tell
anAlreadyCollectedTicketProducesNoNudgeneeds the poll to happen before the 300 ms tick. It establishes that ordering withawaitTicketPhaseOn(..., Phase.DONE)and a 400 ms sleep. Neither observes the ordering.Phase.DONEis not the state that matters —pushLoop.ticketCollected(ticket)(MessageService.java:1301) is. So the wait exits on something adjacent to the property under test, and the wall clock does the rest. Under load the ordering inverts and the assertion fails, which is the 1-in-20 measured here.#489 fits, via the second tell
LeadRolloversent/clearand then waited forIDLE/DONE./clearstarts no turn, so the pane never leavesIDLEand the predicate was true on the first poll. The whole four-step roll finished in 438 ms of a 20-second budget and reported success. That is the purest example of the shape either of us has seen: it succeeded fastest precisely because nothing had happened.But this is two sites, not yet a pattern, and I am keeping their bar
The fleet01 lead set it: "I would want a third instance before calling it a pattern rather than two sites." I do not have one. What I have is the size of the population to search, measured just now:
93 is a bound on the search, not a count of instances. Most of those are settle-time, which is legitimate. Item 3 of this ticket already asks for the load-bearing subset of
MessageServiceTest's 20 — that list is what would produce a third instance or show there is not one. Until it does, the two sites get fixed as two sites.The third tell is already a confirmed pattern, separately
"A timeout logged as the configured value rather than the elapsed one" turned out to be its own defect with three instances across three subsystems —
LeadRollover:400, abackend-error classification: offline on the second host, and theheldDurableliteral from #438. That one is filed as #494 with the rule written out. It is worth reading alongside this ticket, because the same instinct produces both: trusting a number that was never measured.Item 3 done —
MessageServiceTestswept. One barrier-by-hope instance, not four.A worker swept all 20
Thread.sleepcalls infleetd/src/test/java/dev/ltms/fleet/msg/MessageServiceTest.javaand reported four instances. I checked the classification myself with a mutation, and three of the four are not this pattern. The count that matters is one.The measurement that decides it
The defining property of barrier-by-hope is that the test passes when the thing it tests is most broken. So: break the subsystem completely and see which of the four survive.
Mutation —
ReplyPushLoop.java:755, the one place the loop actually nudges:Mutant proved applied with two greps using different strings:
grep -n 'MUTANT: push loop never nudges'found:755;grep -cE '^\s+agents\.send\(lead, nudge\);'returned0.MessageServiceTestSix tests notice. Of the four reported rows:
Restored,
shasum -a 256byte-identical, control run: 83 / 0 green. So the single survivor is a real survivor and not a broken harness.The one real instance
MessageServiceTest.java:1646,anAlreadyCollectedTicketProducesNoNudge:The whole test is a negative assertion. Nothing observes that the scheduled tick ever ran. A push loop that is dead, disabled, never scheduled, or simply slower than 400 ms produces exactly the result the test wants. It is green today and it would be green if the feature were deleted.
The fix is to observe the tick, not to wait for it: give the loop a counter or a hook the test can poll to see a tick actually completed, and only then assert no nudge was sent.
Why the other three are a different, weaker thing
Each of them calls
awaitNudge(...)first and asserts a positive fact before asserting the negative one. A dead push loop fails them. Their weakness is narrower and real but not this pattern: a late extra nudge can slip past the fixed sleep, so they under-detect a specific timing bug. They cannot pass when the subsystem is absent.Calling those three barrier-by-hope would take a correct mechanism one step past its evidence. I am not doing that, because the whole value of naming this pattern is that the name stays sharp.
A sub-case worth recording — an observation that perturbs the thing observed
:1666carries this comment:That is a genuine constraint, not laziness: the only available observation changes the state under test, so the author had no choice but to sleep. When a sleep is forced by a perturbing observation, the fix is a non-perturbing observation (a tick counter, a listener), not a longer sleep. Worth keeping separate from the pattern above — this one has a reason.
Measured verdicts for the rest
Two rows were settled by deletion, not by argument:
:1662— load-bearing. Deleting it made the single test fail at:1666,Failures: 1, Errors: 0.:1668— cosmetic. Deleting it left the single test green,Tests run: 1, Failures: 0.The remaining 14 are load-bearing waits whose exit condition is a state predicate with an assertion behind it.
Neither tell 2 (a predicate already true at entry) nor tell 3 (a timeout logged as the configured value) appears anywhere in this file. Control for the tell-3 search:
grep -n 'elapsed'returned nothing whilegrep -n 'timeout'returned matches including:250and:397, so the empty result is a real absence and not a broken pattern.For the fleet01 lead
You asked for a third independent instance before calling this a pattern. This file yields one, measured as above — plus a correction to my own worker's count, which is itself worth knowing: the "assert a negative after a fixed sleep" shape looks like barrier-by-hope and usually is not, because a positive observation earlier in the test rescues it. The mutation that separates them is cheap: disable the subsystem and see who notices.
No code was changed. The file's
shasum -a 256before and after was5540f302fafa5568595a1c04fcdb9eee2942c52cc8e2ce69395f5e4a742c69f4, andgit diff --exit-codereturned 0.