fix(matchmaker): stop seating world players that have no session

guides/observability.md

@@ -213,9 +213,17 @@ asobi.match.started              asobi.match.finished
 asobi.match.player_joined        asobi.match.player_left
 asobi.matchmaker.queued          asobi.matchmaker.removed
 asobi.matchmaker.deduped         asobi.matchmaker.formed
-asobi.matchmaker.failed
+asobi.matchmaker.failed          asobi.matchmaker.dropped
 ```
 
+`dropped{reason=no_live_session}` counts tickets that were matched but could
+not be seated because the player had disconnected while queued. It is
+deliberately NOT on `[asobi, error]`: on mobile that is the ordinary
+consequence of backgrounding the app or moving between networks, and counting
+it as an error would make the node's error rate track connection churn. A
+rising rate means players are abandoning the queue - look at wait times, not at
+the game.
+
 Queue depth is the number worth watching, and in a cluster it is per-node -
 each node's matchmaker holds its own tickets, so a fleet-wide total is a sum
 across nodes, not a reading from one. See [Clustering](clustering.md).

src/asobi_telemetry.erl

@@ -13,7 +13,8 @@
     matchmaker_deduped/2,
     matchmaker_removed/2,
     matchmaker_formed/3,
-    matchmaker_failed/2
+    matchmaker_failed/2,
+    matchmaker_dropped/2
 ]).
 -export([session_connected/1, session_disconnected/2]).
 -export([
@@ -47,7 +48,8 @@
     | no_effect_handler
     | bad_effects_return
     | bad_zone_busy
-    | bad_zone_dirty.
+    | bad_zone_dirty
+    | join_no_live_session.
 -export_type([game_error_kind/0]).
 -export([economy_transaction/4, store_purchase/3]).
 -export([chat_message_sent/2]).
@@ -94,6 +96,7 @@ events() ->
         [asobi, matchmaker, removed],
         [asobi, matchmaker, formed],
         [asobi, matchmaker, failed],
+        [asobi, matchmaker, dropped],
         [asobi, session, connected],
         [asobi, session, disconnected],
         [asobi, ws, connected],
@@ -333,6 +336,23 @@ matchmaker_removed(PlayerId, Reason) ->
         player_id => PlayerId, reason => Reason
     }).
 
+-doc """
+A ticket that was matched but could not be seated.
+
+Distinct from `[asobi, error]` on purpose: a player disconnecting while queued
+is routine, not a game-code fault, and on mobile it is the ordinary consequence
+of backgrounding the app or moving between networks. Counting it as an error
+would make the node's error rate track connection churn.
+
+`mode` is label-safe on the same grounds as the other matchmaker events;
+`reason` is a bounded atom.
+""".
+-spec matchmaker_dropped(binary(), atom()) -> ok.
+matchmaker_dropped(Mode, Reason) ->
+    telemetry:execute([asobi, matchmaker, dropped], #{count => 1}, #{
+        mode => Mode, reason => Reason
+    }).
+
 -spec matchmaker_formed(binary(), pos_integer(), pos_integer()) -> ok.
 matchmaker_formed(Mode, PlayerCount, WaitMs) ->
     telemetry:execute(

src/lua/bots/asobi_bot_spawner.erl

@@ -298,7 +298,12 @@ fill_queue_with_bots() ->
 fill_mode(Mode, Count) when is_binary(Mode), Count > 0 ->
     ModeConfig = mode_config(Mode),
     BotConfig = maps:get(bots, ModeConfig, #{}),
-    case maps:get(enabled, BotConfig, false) of
+    %% `=:= true` rather than a bare `andalso`: a sys.config `game_modes` entry
+    %% is never shape-validated, so `bots => #{enabled => 1}` is reachable.
+    %% `andalso` raises badarg on it and the old `case` case_clause'd - either
+    %% way this gen_server dies every ?CHECK_INTERVAL and silently loses its
+    %% `known` state. Total is the right shape for operator-supplied config.
+    case maps:get(enabled, BotConfig, false) =:= true andalso fillable(Mode, ModeConfig) of
         true ->
             MinPlayers = bot_min_players(BotConfig),
             %% Never fill past max_players: a match_size=2/max_players=2
@@ -328,6 +333,46 @@ fill_mode(Mode, Count) when is_binary(Mode), Count > 0 ->
 fill_mode(_, _) ->
     ok.
 
+-doc """
+Bots are match-only, and a world mode that declares them is a config error.
+
+`scan_groups/2` starts a bot process only for an `{asobi_match_server, _}` pg
+group, so a bot queued into a WORLD mode never gets a process and never
+registers under `{player, BotId}`. `asobi_world_server` then resolves it to
+`undefined`, seats it with no session and no monitor, and nothing can ever
+remove it - `find_player_by_pid/2` matches on the session pid, so no `DOWN`
+reaches it and `handle_leave/2` is unreachable. The world never empties.
+
+Filling was therefore never going to work on a world mode; it just failed
+silently and leaked a seat per bot. Refused loudly instead, because a game
+declaring `game_type = "world"` alongside a `bots` table has made a mistake it
+otherwise has no way to discover.
+""".
+-spec fillable(binary(), map()) -> boolean().
+fillable(Mode, ModeConfig) ->
+    case maps:get(type, ModeConfig, match) of
+        world ->
+            %% Rate-limited, keyed on the mode: fill_mode/2 runs every
+            %% ?CHECK_INTERVAL for every mode with somebody queued, so an
+            %% unbounded warning here is one line every 8 seconds for as long
+            %% as the misconfiguration lasts. A log an operator learns to
+            %% filter has stopped working. Same shape as log_bot_not_added/3.
+            case asobi_script_log_limiter:allow({?MODULE, bots_on_world_mode, Mode}) of
+                {true, Dropped} ->
+                    ?LOG_WARNING(#{
+                        event => bots_on_world_mode,
+                        msg => ~"bots are declared on a world-type mode; not filling",
+                        mode => Mode,
+                        suppressed_since_last => Dropped
+                    });
+                false ->
+                    ok
+            end,
+            false;
+        _ ->
+            true
+    end.
+
 clamp_fill_target(Target) when Target > ?MAX_BOT_FILL ->
     ?LOG_WARNING(#{
         msg => ~"bot fill target exceeds ceiling, clamping",

src/matches/asobi_matchmaker.erl

@@ -12,6 +12,7 @@ spawns a match, and pushes `match.matched` to each player. A single
 -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2]).
 -ifdef(TEST).
 -export([next_spawn_attempt/1, join_matched_players/3, tally/1, render/3, notify_expired/1]).
+-export([join_if_present/3, discard_unoccupied/4]).
 -endif.
 
 -export_type([snapshot/0, mode_queue/0]).
@@ -153,7 +154,7 @@ snapshot() ->
     Now = erlang:system_time(millisecond),
     try ets:lookup(?SNAPSHOT_TABLE, queue) of
         [{queue, SampledAt, Modes}] when is_integer(SampledAt), is_map(Modes) ->
-            render(SampledAt, Modes, Now);
+            render(SampledAt, narrow_tallies(Modes), Now);
         _ ->
             empty_snapshot()
     catch
@@ -186,7 +187,36 @@ mode_queue(Mode, #{waiting := Waiting, oldest := Oldest, submitted_sum := Sum},
 %% Clamped because system_time can step backwards; a negative wait would be
 %% read as a clock bug in the console rather than on the node.
 -spec waited(integer(), integer()) -> non_neg_integer().
-waited(At, Now) -> max(0, Now - At).
+waited(At, Now) when Now > At -> Now - At;
+waited(_At, _Now) -> 0.
+
+%% `lists:foldl/3` erases the accumulator type, so the ticket map comes back
+%% `term()` and every later use of it is an untyped read. Explicit recursion
+%% keeps it a map: see docs/eqwalizer-idioms.md.
+-spec requeue_failed([map()], map()) -> map().
+requeue_failed([], Tickets) ->
+    Tickets;
+requeue_failed([T | Rest], Tickets) ->
+    requeue_failed(Rest, Tickets#{maps:get(id, T) => T}).
+
+%% The queue snapshot comes back out of ETS as `term()`, and `render/3` wants
+%% the tally shape. Narrow at the boundary rather than letting `dynamic()`
+%% travel: an entry that is not a tally is dropped, because a malformed
+%% snapshot row should cost one mode's numbers, not the whole console page.
+-spec narrow_tallies(map()) -> #{binary() => mode_tally()}.
+narrow_tallies(Modes) ->
+    maps:fold(
+        fun
+            (Mode, #{waiting := W, oldest := O, submitted_sum := S}, Acc) when
+                is_binary(Mode), is_integer(W), W > 0, is_integer(O), is_integer(S)
+            ->
+                Acc#{Mode => #{waiting => W, oldest => O, submitted_sum => S}};
+            (_Mode, _Tally, Acc) ->
+                Acc
+        end,
+        #{},
+        Modes
+    ).
 
 -spec publish(map()) -> ok.
 publish(Tickets) ->
@@ -345,11 +375,7 @@ handle_info(tick, #{tickets := Tickets, tick_interval := Interval, max_wait := M
     {Matched, Expired, Remaining} = process_tickets(Tickets, Now, MaxWait),
     FailedGroups = spawn_matches(Matched),
     notify_expired(Expired),
-    Remaining1 = lists:foldl(
-        fun(T, Acc) when is_map(T), is_map(Acc) -> Acc#{maps:get(id, T) => T} end,
-        Remaining,
-        lists:flatten(FailedGroups)
-    ),
+    Remaining1 = requeue_failed(lists:flatten(FailedGroups), Remaining),
     erlang:send_after(Interval, self(), tick),
     ok = publish(Remaining1),
     {noreply, State#{tickets => Remaining1}};
@@ -573,6 +599,123 @@ join_matched_players(MatchPid, Mode, PlayerIds) ->
             notify_matchmaker_failed(PlayerIds, ~"match_start_failed")
     end.
 
+-doc """
+Seat a matched player in the world, but only while they still have a session.
+
+`asobi_world_server:join/2` takes no session pid and resolves one through
+`pg`. If the player disconnected between taking a ticket and the group being
+formed, it seats them anyway with `session_pid => undefined` and no monitor -
+and that player can then never leave:
+
+- they get no interest subscriptions, so they see nothing;
+- `find_player_by_pid/2` matches on `session_pid =:= Pid`, and `undefined` is
+  never a pid, so no `DOWN` ever resolves to them;
+- `handle_leave/2` is reachable only from an explicit leave or that `DOWN`, so
+  `map_size(Players)` never reaches 0 and the `empty_grace` timer is never even
+  scheduled.
+
+The world then ticks forever around a player who is not there. This is the
+world-side twin of widgrensit/asobi#280, and the same root cause: nothing
+checked that the ticket's owner was still connected before forming.
+
+Checked here rather than refused in `asobi_world_server:join/2`, because
+around twenty tests and the Erlang embedding path join a session-less player
+deliberately - `join/2` is the API for a host that is not driving a WS session.
+(Not, as an earlier draft of this comment claimed, because asobi#277 blessed
+the seat: #277 only stopped `monitor(process, undefined)` from crashing. It
+avoided a crash; it did not sanction the state.)
+
+This screen buys exactly one thing now that `join_if_session/2` re-checks in
+the callback that seats: it keeps the ORDINARY case - a player who left the
+queue - off `[asobi, error]`, where it would make the node's error rate track
+connection churn. It is not what closes the window.
+""".
+-spec join_if_present(pid(), binary(), binary()) -> ok | offline | {error, term()}.
+join_if_present(WorldPid, PlayerId, Mode) ->
+    case asobi_presence:get_status(PlayerId) of
+        offline ->
+            %% `[asobi, matchmaker, dropped]`, not `[asobi, error]`: this fires
+            %% on the EXPECTED path. A player disconnecting while queued is
+            %% routine on mobile, and putting it on the error surface would
+            %% make the node's error rate track connection churn. The world
+            %% server keeps `join_no_live_session` on `[asobi, error]` for the
+            %% plain `join/2` path, and the two rates answer different
+            %% questions.
+            asobi_telemetry:matchmaker_dropped(Mode, no_live_session),
+            offline;
+        online ->
+            %% `require_session` and not `join/2`: the screen above and the
+            %% seat are two separate pg reads, and everything between them -
+            %% the game's join hook, place_player/3, every other member's join
+            %% in this same gen_statem - is inside the window. The world server
+            %% re-checks in the callback that seats, so there is none.
+            case asobi_world_server:join_if_session(WorldPid, PlayerId) of
+                {error, no_live_session} ->
+                    asobi_telemetry:matchmaker_dropped(Mode, no_live_session),
+                    offline;
+                Other ->
+                    Other
+            end
+    end.
+
+%% Explicit recursion: `lists:foldl/3` erases the accumulator type, and the
+%% count is what decides whether the world lives. See docs/eqwalizer-idioms.md.
+-spec seat_group([term()], pid(), binary(), term(), [binary()], non_neg_integer()) ->
+    non_neg_integer().
+seat_group([], _WorldPid, _Mode, _WorldId, _Group, Seated) ->
+    Seated;
+seat_group([PlayerId | Rest], WorldPid, Mode, WorldId, Group, Seated) when is_binary(PlayerId) ->
+    JoinResult = join_if_present(WorldPid, PlayerId, Mode),
+    logger:notice(#{
+        msg => ~"player joined world",
+        player_id => PlayerId,
+        result => JoinResult
+    }),
+    asobi_presence:send(
+        PlayerId,
+        {match_event, matched, #{match_id => WorldId, mode => Mode, player_ids => Group}}
+    ),
+    seat_group(Rest, WorldPid, Mode, WorldId, Group, seated(JoinResult, Seated));
+seat_group([_ | Rest], WorldPid, Mode, WorldId, Group, Seated) ->
+    seat_group(Rest, WorldPid, Mode, WorldId, Group, Seated).
+
+-spec seated(term(), non_neg_integer()) -> non_neg_integer().
+seated(ok, Seated) -> Seated + 1;
+seated(_Other, Seated) -> Seated.
+
+-doc """
+Stop a world nobody was seated in.
+
+The world is built BEFORE anyone joins, and `asobi_world_server` decides it is
+empty in exactly one place - `handle_leave/2`, reachable only from an explicit
+leave or a session `DOWN`. So a world whose roster was never populated never
+arms `empty_grace` and never reaches `finished`: it ticks its whole zone grid
+forever. Screening the departed players out of the join (`join_if_present/3`)
+turns one unremovable seat into zero seats, which is the same terminal state.
+
+Hence the count. If the whole group went offline while queued, the world has
+no reason to exist and is torn down here, where the caller still holds the
+instance pid.
+
+**It counts this group only.** The world is discoverable and quick-play
+eligible from the moment it starts (`spawn_world/6` sets neither `listed` nor
+`quick_play`, and both default to true), so an unrelated player can join it
+while the seat loop is still running and is not counted here. Gating on the
+world's own roster rather than a local tally is the fix; it is not made here.
+""".
+-spec discard_unoccupied(non_neg_integer(), pid(), binary(), term()) -> ok.
+discard_unoccupied(0, InstancePid, Mode, WorldId) ->
+    logger:notice(#{
+        msg => ~"world had no live players to seat; discarding it",
+        mode => Mode,
+        world_id => WorldId
+    }),
+    asobi_telemetry:matchmaker_dropped(Mode, unoccupied),
+    _ = supervisor:terminate_child(asobi_world_instance_sup, InstancePid),
+    ok;
+discard_unoccupied(_Seated, _InstancePid, _Mode, _WorldId) ->
+    ok.
+
 %% Unlike spawn_match, world spawn is detached (spawn/1) to avoid blocking the
 %% matchmaker, so there is no clean handle to re-queue the group on failure.
 %% Worlds therefore fail fast: on the first spawn error/crash the players are
@@ -621,25 +764,10 @@ spawn_world(Mode, ModeConfig, PlayerIds, Group, Rest, Failed) ->
                             }),
                             WorldInfo = asobi_world_server:get_info(WorldPid),
                             WorldId = maps:get(world_id, WorldInfo, undefined),
-                            lists:foreach(
-                                fun(PlayerId) when is_binary(PlayerId) ->
-                                    JoinResult = asobi_world_server:join(WorldPid, PlayerId),
-                                    logger:notice(#{
-                                        msg => ~"player joined world",
-                                        player_id => PlayerId,
-                                        result => JoinResult
-                                    }),
-                                    asobi_presence:send(
-                                        PlayerId,
-                                        {match_event, matched, #{
-                                            match_id => WorldId,
-                                            mode => Mode,
-                                            player_ids => SpawnPlayerIds
-                                        }}
-                                    )
-                                end,
-                                SpawnPlayerIds
-                            );
+                            Seated = seat_group(
+                                SpawnPlayerIds, WorldPid, Mode, WorldId, SpawnPlayerIds, 0
+                            ),
+                            discard_unoccupied(Seated, InstancePid, Mode, WorldId);
                         {error, Reason} ->
                             logger:error(#{
                                 msg => ~"world spawn failed",