Skip to content

fix(test): give the vote-close waits a deadline that covers the DB write - #570

Open
Taure wants to merge 4 commits into
mainfrom
fix/vote-hybrid-close-flake
Open

Taure wants to merge 4 commits into
mainfrom
fix/vote-hybrid-close-flake

Conversation

@Taure

@Taure Taure commented Aug 26, 2026

Copy link
Copy Markdown
Contributor

asobi_vote_SUITE:vote_window_hybrid/1 failed roughly one full rebar3 ct in three or four, and passed every time the suite ran alone.

Why

The close path is not just a state transition. resolve_and_stop/1 runs persist_vote/1 before {stop, normal}, and that is a synchronous asobi_repo:insert/1 - a real Postgres write, on a pool every other suite in the run is also using.

So the gap between the closing cast_vote/3 returning and the DOWN arriving is a contended database round trip, not scheduling jitter, and it is unbounded from the test's point of view. Three of the twenty DOWN waits in this suite used 1000ms against its own 2000ms norm, and all three are the same shape: close the vote, then wait for the server to stop.

Fix

One named await_stop/3 with the reasoning stated once, so the budget cannot drift back down without the next reader seeing what it is waiting on.

Not a product defect. broadcast_vote_result/1 runs before the persist, so a client sees the result immediately and only the process lingers. Persisting before dying is the same choice asobi_zone:terminate/2 makes for its snapshot.

Evidence

run result
full CT, loaded box fail
full CT, serial fail (a later run)
suite alone, ×4 across two branches pass
full CT on an unmodified baseline pass
full CT with this fix 390/390

Reproduced on two different branches, on both a loaded and an idle box, and never with the suite run alone. That is a deadline too tight for what it waits on, not a race in the vote server.

Found while running the review gate on #568 and #569 - it is unrelated to both, which is why it is here rather than folded into either.

Taure added a commit that referenced this pull request Aug 26, 2026
Working the code review. Its blocker is that the previous commit's central
claim was false: `join_if_session/2` did not close the window.

The `require_session` clause resolved the session and then DISCARDED it, and
`handle_join` resolved it again to pick its monitor - with the game module's
join hook and `place_player/3` in between. A session dying inside that hook
therefore produced the exact unremovable seat the clause exists to refuse,
through the function documented as closing the window. The reduction was real
(the other members' joins left the window) but it was a factor of 1/N, not
closure.

The resolved pid is now carried into `handle_join/5` and monitored. That makes
the case self-healing rather than permanent: a monitor on an already-dead pid
delivers `DOWN` immediately, `find_player_by_pid/2` resolves it, and
`handle_leave/2` runs. Pinned by a test that kills the session INSIDE the join
hook; it reports `expected: 0, got: 1` with the fix reverted.

`discard_unoccupied/4`'s tests no longer meck OTP's `supervisor` VM-wide. That
mock asserted only that `terminate_child/2` was CALLED - it stayed green if the
supervisor atom were wrong, if the supervisor were not running, or if the
instance survived, which is every way this can actually break. They run against
a real `simple_one_for_one` now and wait for the instance's `DOWN`.

Doc corrections, all of them claims this branch made and the code does not
support:

- `join_if_present/3` still carried the "the window is one message" paragraph
  that the previous commit's own message rejected, eighteen lines above the
  comment rejecting it. The screen buys one thing - keeping the ordinary case
  off `[asobi, error]` - and that is now all it says.
- `discard_unoccupied/4` claimed the residual race was a player dying between
  the screen and the join. That mechanism is gone; what remains is that the
  count covers this group only, while the world is discoverable and quick-play
  eligible from the moment it starts.
- The `join_no_live_session` comment said the matchmaker screens before this
  point. False for the plain `join/2` path, which is where it is actually
  reached from.
- **A correction to a correction.** The previous commit said the 100 pre-spawned
  zones were "not down to the matchmaker's `grid_size` default". That was wrong:
  `asobi_world_server` defaults `lazy_zones` to `GridSize > 100`, so
  `grid_size => 10` IS what leaves it off. The original diagnosis was right; the
  new information is only that an explicit `lazy_zones = true` cannot help
  either, because the matchmaker never forwards it.

eunit 2408/0; eqwalize-all 192, zero in every touched module; dialyzer and xref
clean. CT is 389/390 on this branch, failing only `asobi_vote_SUITE`'s
pre-existing flake, which is fixed separately in #570 and is unrelated to this
change.
@github-actions

github-actions Bot commented Aug 26, 2026 •

Copy link
Copy Markdown

🟡 Code Coverage — 76.9%

9398 of 12221 lines covered.


🟡 ELP Lint — 192 warnings

212 diagnostics found. See job logs for details.


✅ ELP eqWAlize

No diagnostics.

Taure added 4 commits August 26, 2026 18:08
`asobi_vote_SUITE:vote_window_hybrid/1` failed roughly one full `rebar3 ct` in
three or four, and passed every time the suite ran alone.

The close path is not just a state transition. `resolve_and_stop/1` runs
`persist_vote/1` before `{stop, normal}`, and that is a SYNCHRONOUS
`asobi_repo:insert/1` - a real Postgres write, on a pool every other suite in
the run is also using. So the gap between the closing `cast_vote/3` returning
and the `DOWN` arriving is a contended database round trip, not scheduling
jitter, and it is unbounded from the test's point of view.

Three of the twenty `DOWN` waits in this suite used 1000ms against its own
2000ms norm, and all three are the same shape: close the vote, wait for the
server to stop. They now go through one named `await_stop/3` with the reasoning
stated once, so the budget cannot drift back down without the next reader
seeing why it is what it is.

Not a product defect: `broadcast_vote_result/1` runs BEFORE the persist, so a
client sees the result immediately and only the process lingers. Persisting
before dying is the same choice `asobi_zone:terminate/2` makes for its
snapshot.

Verified with the suite alone twice and a full serial `rebar3 ct` at 390/390.
The failure was reproduced on two different branches, on both a loaded and an
idle box, and does not reproduce with the suite run alone - it is a deadline
that is too tight for what it waits on, not a race in the vote server.
Working the architecture guardian's findings. Two claims in the previous commit
were wrong, and one of the three converted call sites was converted for a
reason that does not apply to it.

`vote_veto/1` declared `window_ms => 5000` and the new deadline was 5000ms. A
veto and a window expiry deliver a byte-identical
`{'DOWN', _, _, _, normal}`, so the fallback could have satisfied the assertion
the veto is supposed to. What kept them apart was that the expiry path runs
`persist_vote/1` and the veto path does not - an accident of latency, not a
margin. Its window is 60000 now, like the other two close tests.

`handle_veto/3` does no write at all, so the helper's stated cause - a
contended database round trip - was false for one of its three uses. The
criterion was "these three had 1000ms where the suite's norm is 2000ms", and
that is what it says now.

5000 is not a bound and no longer claims to be. `minato_pool`'s checkout
timeout is 5000ms and `minato_conn`'s query timeout is 15000ms, so a contended
insert can block the vote server for both before giving up - a derived budget
would be north of 20s, and 5000 happens to coincide with the pool's own
give-up. It is an empirical multiple, the doc block says so, and it says that
if the flake returns the answer is to take the write off the stop path rather
than raise this again.

The product change: `notify_match(resolved, ...)` moves ABOVE `persist_vote/1`.
`broadcast_vote_result/1` is a cast, so the client already had the result - but
the match server, which is what game logic reacts to, was behind the write.
That meant a player could know the outcome while the server had not acted on
it, for as long as the pool was contended. Both notifications are ahead of the
write now.

Also corrected: the previous commit cited `asobi_zone:terminate/2` as
precedent. It is not analogous - the zone snapshots on EVERY exit path, while
this persists only from `closed(enter, ...)` and `terminate/3` is a bare `ok`,
so a vote killed while open writes nothing. Vote persistence is already
best-effort, which means the synchronous placement buys latency cost and no
durability guarantee.

Not fixed here, worth a follow-up: the write still sits on the stop path, so a
vote holds a pool connection between "resolved" and "gone". At a phase boundary
with many matches closing votes at once that serialises on the pool. And a
vetoed vote is never persisted at all, so it leaves no row in the history the
votes API serves.

eunit 2398/0, CT 390/0 serial, vote suite twice alone, eqwalize-all clean on
both touched modules.
Working the security review. Its High is pre-existing and this branch is what
narrows it, so it is closed here rather than filed.

A vote server that is resolving serves nothing and then stops. A
`gen_statem:call/2` landing in that window does not time out - it defaults to
`infinity`, waits for the stop, and then exits the CALLER with
`{normal, {gen_statem, call, _}}`. The callers are `asobi_match_server` and
`asobi_world_server`, calling from inside their own callbacks with no
try/catch, and a compound exit reason is a crash to the supervisor. So one
player's ordinary `vote.cast` frame, landing while a vote closed, dropped every
player in the match - or in the world.

`asobi_ws_handler:vote_call/1` already catches this one layer up, which only
stopped the client noticing; the crash was a layer down. `call_vote/1` now
contains it at all four call sites.

The previous commit's reordering narrowed the window from "the whole Postgres
write" to "the match server's mailbox latency" - measured out of tree at 20s
versus effectively none - but it did not close it, because message order
between the WS process and the vote server is not guaranteed.

Two things the review corrected that I had wrong:

The 500ms grace period is not a duration anyone gets. `closed(enter, ...)` ends
in `{stop, normal, _}`, so the clauses only see a vote already in the mailbox
when that callback runs. **I nearly deleted them as dead code on that basis and
put them back**: a test run with them removed failed, so "can never execute" is
not something I could demonstrate, and removing a safety net on an unproven
claim is the wrong direction. The moduledoc now describes the real window
instead of promising 500ms.

`asobi_zone:terminate/2` was the wrong precedent for persisting on the way out.
The zone snapshots on EVERY exit path; this persists only from
`closed(enter, ...)` and `terminate/3` is a bare `ok`, so a vote killed while
open writes nothing. Vote persistence is already best-effort, which means the
synchronous placement buys latency cost and no durability.

Separately, `asobi_vote_server_tests:grace_period/0` was flaky in its own right
- 180ms into a 200ms window, so the second vote raced the deadline it was
asserting inside. Measured failing two runs in four on an UNMODIFIED checkout.
It is now `late_vote_is_counted/0` with 800ms of margin in a 1000ms window,
green six runs for six, and its name and comment say what it actually covers -
which is not `?GRACE_MS`.

Also clears four pre-existing eqwalizer errors in asobi_match_server, since CI
checks every module a PR touches: `?LOG_INFO` returning term() in a function
spec'd `-> ok`, a player id off the wire typed `binary()` in a log helper, and
an ETS crash-recovery read indexed without a map guard.

Not fixed here, worth follow-ups: the write still sits on the stop path, so a
vote holds a pool connection between "resolved" and "gone"; a vetoed vote is
never persisted and emits no telemetry, so nothing durable records that it
happened or who did it; and `asobi_vote_controller:show/1` has no participant
check, unlike `index/1`.

eunit 2398/0, CT 390/0 serial, eqwalize-all 193 and clean on every touched
module.
Working the code review. Its blocker is a regression I introduced two commits
ago and no tool could see.

**`-behaviour(gen_statem).` was gone.** The moduledoc rewrite ate the line
beneath it, and because the attribute is compile-time only, xref, dialyzer and
eqwalizer all stayed green while `asobi_vote_server` became the only gen_statem
in `src/` without it - losing callback verification and the ex_doc behaviour
link. Restored.

The containment moves from four copies in `asobi_match_server` and
`asobi_world_server` into `asobi_vote_server:cast_vote/3` and `cast_veto/2`.
What is being contained is this module's protocol - it stops without replying -
not a property of its callers, and the local copies erased the return type
(`term()` where both call sites match on `ok | {error, term()}`) and caught
`{normal, _}` broadly enough to swallow an unrelated 2-tuple. The catch now
pins the full `{Reason, {gen_statem, call, _}}` shape, so a genuine crash
(`{{badmatch, _}, {gen_statem, call, _}}`) still takes the caller down.

**The call is bounded, which the previous commit missed entirely.** Containing
the exit turned "the match dies" into "the match freezes": `gen_statem:call/2`
defaults to `infinity`, so a caller landing while the vote is inside
`persist_vote/1` waited out the whole write - up to the pool's 5s checkout plus
a 15s query, with every player's input behind it. `?CALL_TIMEOUT` makes that one
refused vote (`{error, vote_busy}`) instead.

**The `?GRACE_MS` clauses are gone after all.** The previous commit put them
back because a test failed with them removed; that test was the 2-in-4 flake
the same commit was fixing, so it proved nothing. The review demonstrated the
clauses are unreachable - a gen_statem runs `closed(enter, ...)` before
dispatching anything queued, and that callback stops the process - so the
mailbox window I claimed was real does not exist.

`guides/voting.md` still published the 500ms grace as a product feature. That
is the fourth doc-claims-what-the-code-does-not-do on this branch and the first
one customers read; it is retracted rather than reworded.

Three tests for the containment, which had none: a dead server, a server that
stops without replying, and a wedged one. All three are driven through a real
`gen_statem:call` rather than a hand-raised exit, so they still fail if the
wrapping shape changes - and all three fail with the fix reverted.

`late_vote_is_counted/0` sleeps 800ms of a 1000ms window, not 200ms. The
previous commit widened the margin by moving the vote to 20% in, which stopped
it being a late vote at all - the property it is named for. 80% in with 200ms
of margin keeps both.

`await_stop/3` reports an abnormal exit reason instead of burning the deadline
and blaming the close.

eunit 30/0 on the vote module with all three new tests discriminating; full
suites next.
@Taure
Taure force-pushed the fix/vote-hybrid-close-flake branch from 6d7f50d to 8826ec9 Compare August 26, 2026 16:18
Taure added a commit that referenced this pull request Aug 26, 2026
Working the code review. Its blocker is that the previous commit's central
claim was false: `join_if_session/2` did not close the window.

The `require_session` clause resolved the session and then DISCARDED it, and
`handle_join` resolved it again to pick its monitor - with the game module's
join hook and `place_player/3` in between. A session dying inside that hook
therefore produced the exact unremovable seat the clause exists to refuse,
through the function documented as closing the window. The reduction was real
(the other members' joins left the window) but it was a factor of 1/N, not
closure.

The resolved pid is now carried into `handle_join/5` and monitored. That makes
the case self-healing rather than permanent: a monitor on an already-dead pid
delivers `DOWN` immediately, `find_player_by_pid/2` resolves it, and
`handle_leave/2` runs. Pinned by a test that kills the session INSIDE the join
hook; it reports `expected: 0, got: 1` with the fix reverted.

`discard_unoccupied/4`'s tests no longer meck OTP's `supervisor` VM-wide. That
mock asserted only that `terminate_child/2` was CALLED - it stayed green if the
supervisor atom were wrong, if the supervisor were not running, or if the
instance survived, which is every way this can actually break. They run against
a real `simple_one_for_one` now and wait for the instance's `DOWN`.

Doc corrections, all of them claims this branch made and the code does not
support:

- `join_if_present/3` still carried the "the window is one message" paragraph
  that the previous commit's own message rejected, eighteen lines above the
  comment rejecting it. The screen buys one thing - keeping the ordinary case
  off `[asobi, error]` - and that is now all it says.
- `discard_unoccupied/4` claimed the residual race was a player dying between
  the screen and the join. That mechanism is gone; what remains is that the
  count covers this group only, while the world is discoverable and quick-play
  eligible from the moment it starts.
- The `join_no_live_session` comment said the matchmaker screens before this
  point. False for the plain `join/2` path, which is where it is actually
  reached from.
- **A correction to a correction.** The previous commit said the 100 pre-spawned
  zones were "not down to the matchmaker's `grid_size` default". That was wrong:
  `asobi_world_server` defaults `lazy_zones` to `GridSize > 100`, so
  `grid_size => 10` IS what leaves it off. The original diagnosis was right; the
  new information is only that an explicit `lazy_zones = true` cannot help
  either, because the matchmaker never forwards it.

eunit 2408/0; eqwalize-all 192, zero in every touched module; dialyzer and xref
clean. CT is 389/390 on this branch, failing only `asobi_vote_SUITE`'s
pre-existing flake, which is fixed separately in #570 and is unrelated to this
change.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant