diff --git a/lib/wanderer_app/character/tracker.ex b/lib/wanderer_app/character/tracker.ex index 587dd4411..05319831f 100644 --- a/lib/wanderer_app/character/tracker.ex +++ b/lib/wanderer_app/character/tracker.ex @@ -233,6 +233,33 @@ defmodule WandererApp.Character.Tracker do # Re-raise to maintain existing error handling reraise error, __STACKTRACE__ end + + # The state write above rewrites track_location on every online + # transition, and did so with no telemetry at all: + # maybe_stop_tracking/2 has :location_flag_cleared and + # maybe_start_location_tracking/2 has :location_flag_repaired, + # but this path had nothing. + # + # An online=false transition pauses location updates until EVE + # reports the character online again. For a real logout that is + # correct behaviour, not a defect — update_location/1's clause + # below says as much. This counter exists because the pause is + # indistinguishable from the intermittent tracking loss users + # report, and there was previously no way to see the rate at + # all, let alone spot a spurious offline reading from ESI. + # Treat a rise here as a lead, not an incident. + # + # Emitted after the write, so a raised state update is not + # counted as a transition that took effect. + :telemetry.execute( + [:wanderer_app, :character, :tracking, :online_transition], + %{count: 1, system_time: System.system_time()}, + %{ + character_id: character_id, + online: online.online, + has_active_maps: Map.get(character_state, :active_maps, []) != [] + } + ) end :ok diff --git a/lib/wanderer_app/map/map_server.ex b/lib/wanderer_app/map/map_server.ex index 22ed3bdd3..7243f1f5f 100644 --- a/lib/wanderer_app/map/map_server.ex +++ b/lib/wanderer_app/map/map_server.ex @@ -30,7 +30,7 @@ defmodule WandererApp.Map.Server do end end - defdelegate untrack_characters(map_id, character_ids), to: Impl + defdelegate untrack_characters(map_id, character_ids, reason), to: Impl defdelegate add_system(map_id, system_info, user_id, character_id, opts \\ []), to: Impl diff --git a/lib/wanderer_app/map/server/map_server_characters_impl.ex b/lib/wanderer_app/map/server/map_server_characters_impl.ex index 4cf518305..376cebbb8 100644 --- a/lib/wanderer_app/map/server/map_server_characters_impl.ex +++ b/lib/wanderer_app/map/server/map_server_characters_impl.ex @@ -77,11 +77,17 @@ defmodule WandererApp.Map.Server.CharactersImpl do end) end - def untrack_characters(map_id, character_ids) do + # `reason` is threaded from the caller rather than assumed. Three unrelated + # causes converge here — presence expiry, an ACL permission sweep, and a user + # clicking untrack in the UI — and this function previously stamped all three + # as :presence_expired on the tracking telemetry. That sent anyone reading the + # metric to investigate browser disconnects for what was actually a + # permissions change. + def untrack_characters(map_id, character_ids, reason) do if length(character_ids) > 0 do Logger.debug(fn -> "[CharactersImpl] Untracking #{length(character_ids)} characters from map #{map_id} - " <> - "reason: characters no longer in presence_character_ids (grace period expired or user disconnected)" + "reason: #{reason}" end) end @@ -90,21 +96,21 @@ defmodule WandererApp.Map.Server.CharactersImpl do character_map_active = is_character_map_active?(map_id, character_id) character_map_active - |> untrack_character(map_id, character_id) + |> untrack_character(map_id, character_id, reason) end) end - defp untrack_character(true, map_id, character_id) do + defp untrack_character(true, map_id, character_id, reason) do Logger.info(fn -> "[CharactersImpl] Untracking character #{character_id} from map #{map_id} - " <> - "character was actively tracking this map" + "character was actively tracking this map, reason: #{reason}" end) # Emit telemetry for tracking :telemetry.execute( [:wanderer_app, :character, :tracking, :stopped], %{system_time: System.system_time()}, - %{character_id: character_id, map_id: map_id, reason: :presence_expired} + %{character_id: character_id, map_id: map_id, reason: reason} ) WandererApp.Character.TrackerManager.update_track_settings(character_id, %{ @@ -113,7 +119,7 @@ defmodule WandererApp.Map.Server.CharactersImpl do }) end - defp untrack_character(false, map_id, character_id) do + defp untrack_character(false, map_id, character_id, _reason) do Logger.debug(fn -> "[CharactersImpl] Skipping untrack for character #{character_id} on map #{map_id} - " <> "character was not actively tracking this map" @@ -325,7 +331,7 @@ defmodule WandererApp.Map.Server.CharactersImpl do ) map_id - |> untrack_characters(character_ids) + |> untrack_characters(character_ids, :permission_revoked) map_id |> WandererApp.MapCharacterSettingsRepo.get_by_map_filtered(character_ids) diff --git a/lib/wanderer_app/map/server/map_server_impl.ex b/lib/wanderer_app/map/server/map_server_impl.ex index 30fec738c..57d2291cc 100644 --- a/lib/wanderer_app/map/server/map_server_impl.ex +++ b/lib/wanderer_app/map/server/map_server_impl.ex @@ -219,7 +219,7 @@ defmodule WandererApp.Map.Server.Impl do defdelegate cleanup_systems(map_id), to: SystemsImpl defdelegate cleanup_connections(map_id), to: ConnectionsImpl defdelegate cleanup_characters(map_id), to: CharactersImpl - defdelegate untrack_characters(map_id, characters_ids), to: CharactersImpl + defdelegate untrack_characters(map_id, characters_ids, reason), to: CharactersImpl defdelegate add_system(map_id, system_info, user_id, character_id, opts \\ []), to: SystemsImpl defdelegate paste_connections(map_id, connections, user_id, character_id), to: ConnectionsImpl defdelegate paste_systems(map_id, systems, user_id, character_id, opts), to: SystemsImpl @@ -740,7 +740,7 @@ defmodule WandererApp.Map.Server.Impl do ) end - CharactersImpl.untrack_characters(map_id, not_present_character_ids) + CharactersImpl.untrack_characters(map_id, not_present_character_ids, :presence_expired) broadcast!( map_id, diff --git a/lib/wanderer_app/metrics/prom_ex_plugin.ex b/lib/wanderer_app/metrics/prom_ex_plugin.ex index b12951742..d281ce1f8 100644 --- a/lib/wanderer_app/metrics/prom_ex_plugin.ex +++ b/lib/wanderer_app/metrics/prom_ex_plugin.ex @@ -35,6 +35,56 @@ defmodule WandererApp.Metrics.PromExPlugin do :location_skipped_while_active ] + # Tracking-lifecycle instrumentation. The three location_flag counters above + # only cover the flag defect fixed in #146; these cover the neighbouring paths + # that could stop a character updating on the map. + # + # The first three were already being emitted at their call sites with no + # handler attached anywhere, so nothing was reaching Prometheus. The fourth, + # online_transition, is emitted for the first time by this change. + # + # stopped - tracking ended. `reason` is threaded from the caller + # (:presence_expired, :permission_revoked, + # :user_untracked); it used to be hardcoded to + # :presence_expired for all three causes + # permission_revoked - ACL check removed characters (no grace period). + # A sum, not a counter: one event carries a whole batch + # token_refresh_failed - ESI refresh failed. Only the invalid_grant variety + # wipes a token, and only 3 within the 2h counter TTL + # online_transition - update_online/1 rewrote track_location because EVE + # online status flipped. A genuine logout lands here + # too and is NOT a defect (see update_location/1's + # comment); this counter exists to show the rate and + # catch spurious offline reports, not to be alerted on + @tracking_stopped_event [:wanderer_app, :character, :tracking, :stopped] + @tracking_permission_revoked_event [ + :wanderer_app, + :character, + :tracking, + :permission_revoked + ] + @tracking_online_transition_event [ + :wanderer_app, + :character, + :tracking, + :online_transition + ] + @token_refresh_failed_event [:wanderer_app, :token, :refresh_failed] + + # Named :tracker, not :tracking — one letter from the events above, and just + # as capable of ending a character's location updates. + # + # Its sibling [:character, :tracker, :stopped] is NOT declared here: it is + # already registered by character_event_metrics/0. Declaring it again would + # collide on the metric name, and the registry resolves a collision by logging + # a warning and skipping one of them. + @tracker_untracked_from_map_event [ + :wanderer_app, + :character, + :tracker, + :untracked_from_map + ] + # ESI-related events @esi_rate_limited_event [:wanderer_app, :esi, :rate_limited] @esi_error_event [:wanderer_app, :esi, :error] @@ -51,10 +101,25 @@ defmodule WandererApp.Metrics.PromExPlugin do user_event_metrics(), map_event_metrics(), map_subscription_metrics(), - # Registered as a base metric on purpose: this instrumentation exists to - # catch a rare, hard-to-reproduce defect, so it must not be switched off - # by WANDERER_BASE_METRICS_ONLY. Three counters, no tags — negligible cost. - location_tracking_defect_metrics() + # Registered as base metrics on purpose: this instrumentation exists to + # catch rare, hard-to-reproduce defects, so it must not be switched off by + # WANDERER_BASE_METRICS_ONLY. + # + # Most of these carry a :character_id tag (permission_revoked is the + # exception — it reports a batch, so it is tagged by :map_id). That is a + # deliberate reversal of the original "no tags" choice: an untagged + # counter can say a freeze happened N times but never which character, and + # every report these exist to serve names one pilot. + # + # Cardinality is roughly (characters x ~10), since online_transition and + # token_refresh_failed each multiply by their own small tag sets. That is + # fine at this deployment's size but is NOT free: series are never + # reclaimed, so characters that have since been deleted keep their rows + # for the life of the VM. Revisit if the character count grows by orders + # of magnitude. online_transition in particular fires on every EVE login + # and logout, so unlike the defect counters it is not rare. + location_tracking_defect_metrics(), + tracking_lifecycle_metrics() ] advanced_metrics = [ @@ -80,8 +145,8 @@ defmodule WandererApp.Metrics.PromExPlugin do event_name: @location_flag_cleared_event, description: "Times location tracking was cleared while the character was still online in EVE", - tags: [], - tag_values: &get_empty_tag_values/1 + tags: [:character_id], + tag_values: &get_character_tag_values/1 ), counter( @location_flag_repaired_event ++ [:count], @@ -89,8 +154,8 @@ defmodule WandererApp.Metrics.PromExPlugin do description: "Times an online character's location tracking was restored on map re-entry, " <> "each of which would previously have frozen on the map", - tags: [], - tag_values: &get_empty_tag_values/1 + tags: [:character_id], + tag_values: &get_character_tag_values/1 ), counter( @location_skipped_while_active_event ++ [:count], @@ -98,8 +163,8 @@ defmodule WandererApp.Metrics.PromExPlugin do description: "Character-minutes during which an online, map-active character had location " <> "tracking disabled; expected to be zero", - tags: [], - tag_values: &get_empty_tag_values/1 + tags: [:character_id], + tag_values: &get_character_tag_values/1 ) ] ) @@ -138,12 +203,16 @@ defmodule WandererApp.Metrics.PromExPlugin do tags: [], tag_values: &get_empty_tag_values/1 ), + # Tagged for the same reason as the tracking-lifecycle counters: this + # event already carries character_id and reason (:garbage_collection), + # and a tracker stopping is one of the ways a character silently stops + # being polled. counter( @character_tracker_stopped_event ++ [:count], event_name: @character_tracker_stopped_event, description: "The number of character tracker stopped events that have occurred", - tags: [], - tag_values: &get_empty_tag_values/1 + tags: [:character_id, :reason], + tag_values: &get_tracking_stopped_tag_values/1 ) ] ) @@ -297,6 +366,105 @@ defmodule WandererApp.Metrics.PromExPlugin do } end + defp tracking_lifecycle_metrics do + Event.build( + :wanderer_app_tracking_lifecycle_metrics, + [ + counter( + @tracking_stopped_event ++ [:count], + event_name: @tracking_stopped_event, + description: + "Times tracking was stopped for a character on a map, tagged with the cause: " <> + "presence_expired (browser gone past the grace period, not an EVE logout), " <> + "permission_revoked (ACL sweep) or user_untracked (clicked in the UI)", + tags: [:character_id, :reason], + tag_values: &get_tracking_stopped_tag_values/1 + ), + # sum/2, not counter/2: this event fires once per batch and carries the + # batch size in its :count measurement. A counter ignores measurements + # entirely, so an ACL sweep removing 40 characters would increment it by + # 1 — and this metric is meant to be read against :stopped, which fires + # 40 times for that same sweep. + sum( + @tracking_permission_revoked_event ++ [:count], + event_name: @tracking_permission_revoked_event, + measurement: :count, + description: + "Characters removed from a map by the ACL permission check, which untracks them " <> + "in the database with no grace period", + tags: [:map_id, :reason], + tag_values: &get_permission_revoked_tag_values/1 + ), + counter( + @tracking_online_transition_event ++ [:count], + event_name: @tracking_online_transition_event, + description: + "Times EVE online status flipped for a character, rewriting track_location. " <> + "online=false with active maps is a silent pause in location updates", + tags: [:character_id, :online, :has_active_maps], + tag_values: &get_online_transition_tag_values/1 + ), + counter( + @token_refresh_failed_event ++ [:count], + event_name: @token_refresh_failed_event, + description: + "ESI token refresh failures. Three consecutive invalid_grant results wipe the " <> + "token, after which every poll for that character skips silently", + tags: [:character_id, :error_type], + tag_values: &get_token_refresh_tag_values/1 + ), + counter( + @tracker_untracked_from_map_event ++ [:count], + event_name: @tracker_untracked_from_map_event, + description: + "Characters untracked from a map by the tracker manager's delayed untrack queue", + tags: [:character_id, :reason], + tag_values: &get_tracking_stopped_tag_values/1 + ) + ] + ) + end + + defp get_character_tag_values(metadata) do + %{character_id: Map.get(metadata, :character_id, "unknown")} + end + + defp get_tracking_stopped_tag_values(metadata) do + %{ + character_id: Map.get(metadata, :character_id, "unknown"), + reason: Map.get(metadata, :reason, "unknown") + } + end + + # Tagged by map rather than character: this event reports a batch removal and + # carries :character_ids (a list), so there is no single character to name. + # + # `reason` is inspected here but passed through raw for :stopped. That is not + # an oversight: :stopped emits a plain atom, while this event's reason reaches + # permission_removal_reason_to_string/1's catch-all clause, which exists + # precisely because the value is not guaranteed to be an atom. + defp get_permission_revoked_tag_values(metadata) do + %{ + map_id: Map.get(metadata, :map_id, "unknown"), + reason: inspect(Map.get(metadata, :reason, "unknown")) + } + end + + defp get_online_transition_tag_values(metadata) do + %{ + character_id: Map.get(metadata, :character_id, "unknown"), + online: Map.get(metadata, :online, "unknown"), + has_active_maps: Map.get(metadata, :has_active_maps, "unknown") + } + end + + defp get_token_refresh_tag_values(metadata) do + %{ + character_id: Map.get(metadata, :character_id, "unknown"), + error_type: Map.get(metadata, :error_type, "unknown") + } + end + defp get_empty_tag_values(_) do %{} end diff --git a/lib/wanderer_app_web/live/map/map_characters_live.ex b/lib/wanderer_app_web/live/map/map_characters_live.ex index f09783967..f0e5d1d73 100755 --- a/lib/wanderer_app_web/live/map/map_characters_live.ex +++ b/lib/wanderer_app_web/live/map/map_characters_live.ex @@ -84,7 +84,11 @@ defmodule WandererAppWeb.MapCharactersLive do character_setting -> case character_setting.tracked do true -> - WandererApp.Map.Server.untrack_characters(map_id, [character_setting.character_id]) + WandererApp.Map.Server.untrack_characters( + map_id, + [character_setting.character_id], + :user_untracked + ) socket |> put_flash(:info, "Character untracked!") |> load_characters() diff --git a/test/unit/metrics/prom_ex_plugin_test.exs b/test/unit/metrics/prom_ex_plugin_test.exs new file mode 100644 index 000000000..1b8506bfc --- /dev/null +++ b/test/unit/metrics/prom_ex_plugin_test.exs @@ -0,0 +1,188 @@ +defmodule WandererApp.Metrics.PromExPluginTest do + @moduledoc """ + Guards the tracking instrumentation's ability to answer the question it exists + for: "why did *this* character stop being tracked?" + + Three counters shipped with `tags: []` and a `get_empty_tag_values/1` that + discarded the `character_id` their call sites already provide. The counters + could therefore report that a freeze happened N times but never to whom, which + is the only form the question is ever asked in. Three further events were + emitted at their call sites with no handler attached at all, so they never + reached Prometheus; `:online_transition` is emitted for the first time by the + same change these tests cover. + + These tests fail if either regression is reintroduced. + """ + + use ExUnit.Case, async: true + + alias WandererApp.Metrics.PromExPlugin + + defp metrics do + [] + |> PromExPlugin.event_metrics() + |> List.wrap() + |> Enum.flat_map(& &1.metrics) + end + + defp find!(name) do + case Enum.find(metrics(), &(&1.name == name)) do + nil -> flunk("no metric registered for #{inspect(name)}") + metric -> metric + end + end + + # Every metric whose whole purpose is diagnosing lost tracking. + @tracking_metrics [ + [:wanderer_app, :character, :tracking, :location_flag_cleared, :count], + [:wanderer_app, :character, :tracking, :location_flag_repaired, :count], + [:wanderer_app, :character, :tracking, :location_skipped_while_active, :count], + [:wanderer_app, :character, :tracking, :stopped, :count], + [:wanderer_app, :character, :tracking, :permission_revoked, :count], + [:wanderer_app, :character, :tracking, :online_transition, :count], + [:wanderer_app, :character, :tracker, :stopped, :count], + [:wanderer_app, :character, :tracker, :untracked_from_map, :count], + [:wanderer_app, :token, :refresh_failed, :count] + ] + + describe "metric names are unique" do + # A duplicate metric name is not an error: the Prometheus registry logs a + # warning and skips one of the two definitions, so the loser silently never + # records. [:character, :tracker, :stopped] is the live trap here — it is + # declared by character_event_metrics/0 and is one letter away from the + # :tracking event names. + test "no two registered metrics share a name" do + names = Enum.map(metrics(), & &1.name) + duplicates = names -- Enum.uniq(names) + + assert duplicates == [], + "duplicate metric names #{inspect(Enum.uniq(duplicates))}; the registry would " <> + "silently skip one definition" + end + end + + describe "tag_values / tags contract" do + # TelemetryMetricsPrometheus.Core.Counter drops the event entirely when + # tag_values/1 omits any declared tag (validate_tags_in_tag_values/2), and + # reports it only via Logger.debug — which production never sees, since it + # runs at :info. A tag added to `tags:` without a matching key in the + # tag_values function would therefore silently stop the metric recording, + # which is the exact failure mode this instrumentation exists to escape. + test "every tracking metric returns all of its declared tags, even for empty metadata" do + for name <- @tracking_metrics do + metric = find!(name) + returned = metric.tag_values.(%{}) + missing = Enum.reject(metric.tags, &Map.has_key?(returned, &1)) + + assert missing == [], + "#{inspect(name)} declares tags #{inspect(metric.tags)} but tag_values/1 " <> + "omitted #{inspect(missing)}; the Prometheus reporter would silently drop " <> + "every event for this metric" + end + end + end + + describe "location tracking defect counters" do + test "carry character_id so a counter can be traced to a pilot" do + for event <- [ + :location_flag_cleared, + :location_flag_repaired, + :location_skipped_while_active + ] do + metric = find!([:wanderer_app, :character, :tracking, event, :count]) + + assert :character_id in metric.tags, + "#{event} dropped its character_id tag; it can no longer name the affected pilot" + end + end + + test "tag_values actually propagates character_id from event metadata" do + metric = find!([:wanderer_app, :character, :tracking, :location_flag_repaired, :count]) + + assert %{character_id: "char-1"} = metric.tag_values.(%{character_id: "char-1"}) + end + + test "tag_values does not crash on metadata missing character_id" do + metric = find!([:wanderer_app, :character, :tracking, :location_flag_cleared, :count]) + + assert %{character_id: "unknown"} = metric.tag_values.(%{}) + end + end + + describe "previously unhandled tracking lifecycle events" do + test "tracking stopped is registered and keeps the reason" do + metric = find!([:wanderer_app, :character, :tracking, :stopped, :count]) + + assert :reason in metric.tags + assert :character_id in metric.tags + + assert %{reason: :presence_expired, character_id: "char-1"} = + metric.tag_values.(%{reason: :presence_expired, character_id: "char-1"}) + end + + test "permission revoked is tagged by map, since it reports a batch" do + metric = find!([:wanderer_app, :character, :tracking, :permission_revoked, :count]) + + # The event carries :character_ids (a list), so there is no single + # character to name — tagging by character_id here would be a silent lie. + assert :map_id in metric.tags + refute :character_id in metric.tags + end + + test "permission revoked sums the batch size instead of counting events" do + metric = find!([:wanderer_app, :character, :tracking, :permission_revoked, :count]) + + # A Counter ignores measurements and increments by 1 per event, so an ACL + # sweep removing 40 characters would register as 1 — while :stopped fires + # 40 times for that same sweep. The two are meant to be read against each + # other, so this must be a Sum over the :count measurement. + assert %Telemetry.Metrics.Sum{} = metric + assert metric.measurement == :count + end + + test "the tracker-level untrack path is registered too" do + # One letter from :tracking — the delayed untrack queue, previously with + # no handler at all. + metric = find!([:wanderer_app, :character, :tracker, :untracked_from_map, :count]) + + assert :character_id in metric.tags + assert :reason in metric.tags + end + + test "tracker stopped keeps the character and reason it already emitted" do + metric = find!([:wanderer_app, :character, :tracker, :stopped, :count]) + + assert :character_id in metric.tags + + assert %{reason: :garbage_collection, character_id: "char-1"} = + metric.tag_values.(%{reason: :garbage_collection, character_id: "char-1"}) + end + + test "online transition records direction and whether maps were active" do + metric = find!([:wanderer_app, :character, :tracking, :online_transition, :count]) + + assert :online in metric.tags + assert :has_active_maps in metric.tags + + assert %{online: false, has_active_maps: true} = + metric.tag_values.(%{ + character_id: "char-1", + online: false, + has_active_maps: true + }) + end + + test "token refresh failure is registered with its error type" do + metric = find!([:wanderer_app, :token, :refresh_failed, :count]) + + assert :error_type in metric.tags + + assert %{error_type: "invalid_grant", character_id: "char-1"} = + metric.tag_values.(%{ + character_id: "char-1", + error_type: "invalid_grant", + time_since_expiry: 12 + }) + end + end +end