diff --git a/lib/wanderer_app/metrics/prom_ex_plugin.ex b/lib/wanderer_app/metrics/prom_ex_plugin.ex index d281ce1f8..1f41011d3 100644 --- a/lib/wanderer_app/metrics/prom_ex_plugin.ex +++ b/lib/wanderer_app/metrics/prom_ex_plugin.ex @@ -85,6 +85,18 @@ defmodule WandererApp.Metrics.PromExPlugin do :untracked_from_map ] + # The database-level uncheck. Emitted from MapCharacterSettingsRepo.untrack/1, + # which every writer of `tracked: false` funnels through — the UI toggle, the + # ACL sweep and character deletion alike. Tagged by :source so a dashboard + # separates them; a :source of "unknown" means a caller nobody has accounted + # for, and the accompanying log line carries its stacktrace. + @character_settings_untracked_event [ + :wanderer_app, + :map, + :character_settings, + :untracked + ] + # ESI-related events @esi_rate_limited_event [:wanderer_app, :esi, :rate_limited] @esi_error_event [:wanderer_app, :esi, :error] @@ -420,11 +432,27 @@ defmodule WandererApp.Metrics.PromExPlugin do "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 + ), + counter( + @character_settings_untracked_event ++ [:count], + event_name: @character_settings_untracked_event, + description: + "Times a character's tracking box was unchecked in the database, tagged with the " <> + "code path responsible. source=unknown means an unaccounted-for caller", + tags: [:character_id, :source], + tag_values: &get_untracked_tag_values/1 ) ] ) end + defp get_untracked_tag_values(metadata) do + %{ + character_id: Map.get(metadata, :character_id, "unknown"), + source: Map.get(metadata, :source, "unknown") + } + end + defp get_character_tag_values(metadata) do %{character_id: Map.get(metadata, :character_id, "unknown")} end diff --git a/lib/wanderer_app/repositories/map_character_settings_repo.ex b/lib/wanderer_app/repositories/map_character_settings_repo.ex index 584b984c0..c942461c9 100644 --- a/lib/wanderer_app/repositories/map_character_settings_repo.ex +++ b/lib/wanderer_app/repositories/map_character_settings_repo.ex @@ -27,14 +27,36 @@ defmodule WandererApp.MapCharacterSettingsRepo do def update(map_id, character_id, updated_settings) do case get(map_id, character_id) do {:ok, settings} when not is_nil(settings) -> + # This function takes arbitrary attributes, so a caller passing + # tracked: false would flip the flag without going through untrack/1 and + # the uncheck would never be recorded — silently breaking the guarantee + # that untrack/1 observes every one. Nothing does that today; this keeps + # the guarantee true if something ever starts. + untracking? = Map.get(settings, :tracked) == true and untracks?(updated_settings) + settings |> WandererApp.Api.MapCharacterSettings.update(updated_settings) + |> case do + {:ok, _updated} = result -> + if untracking?, do: report_untrack(map_id, character_id) + result + + error -> + error + end _ -> {:ok, nil} end end + # Ash accepts atom or string keys, so check both rather than trusting callers. + defp untracks?(attrs) when is_map(attrs) do + Map.get(attrs, :tracked, Map.get(attrs, "tracked")) == false + end + + defp untracks?(_attrs), do: false + def get_tracked_by_map_filtered(map_id, character_ids), do: WandererApp.Api.MapCharacterSettings.tracked_by_map_filtered(%{ @@ -72,13 +94,37 @@ defmodule WandererApp.MapCharacterSettingsRepo do end end + # Every path that unchecks a character's tracking box in the database funnels + # through here: the UI toggle (TrackingUtils), the ACL permission sweep + # (CharactersImpl) and character deletion (CharactersLive) all call this, and + # untrack!/1 delegates to it. It is therefore the one place that can observe an + # uncheck regardless of which path caused it. + # + # That matters because users report their tracking box unchecking itself while + # none of the known callers appears responsible. Reasoning backwards from the + # call sites could not settle it; recording the caller at the moment of the + # write does. The stacktrace is the payload — it names the path even if the + # path is one nobody has thought of yet. def untrack(%{map_id: map_id, character_id: character_id}) do # First ensure the record exists (get creates if not exists) case get(map_id, character_id) do {:ok, settings} when not is_nil(settings) -> - # Now update the tracked field + # Captured before the update, so this reports the true -> false + # transition rather than every call. A repeat untrack of an already + # untracked character changes nothing and must not be counted, or the + # metric stops meaning "a box was unchecked". + was_tracked = Map.get(settings, :tracked) == true + settings |> WandererApp.Api.MapCharacterSettings.update(%{tracked: false}) + |> case do + {:ok, _updated} = result -> + if was_tracked, do: report_untrack(map_id, character_id) + result + + error -> + error + end error -> Logger.error( @@ -89,6 +135,65 @@ defmodule WandererApp.MapCharacterSettingsRepo do end end + # Known callers, mapped to a bounded set of sources so the metric can be + # grouped in Grafana. Anything else is :unknown — which is exactly the case + # worth looking at, and the log line carries the raw stack for it. + @untrack_sources %{ + WandererApp.Character.TrackingUtils => :ui_toggle, + WandererApp.Map.Server.CharactersImpl => :acl_sweep, + WandererAppWeb.CharactersLive => :character_deleted + } + + defp report_untrack(map_id, character_id) do + {source, stack} = untrack_source() + + Logger.warning( + "[MapCharacterSettings] Untracked character #{character_id} on map #{map_id} " <> + "(source: #{source}). Caller: #{stack}", + character_id: character_id, + map_id: map_id + ) + + :telemetry.execute( + [:wanderer_app, :map, :character_settings, :untracked], + %{count: 1, system_time: System.system_time()}, + %{character_id: character_id, map_id: map_id, source: source} + ) + end + + defp untrack_source do + case Process.info(self(), :current_stacktrace) do + {:current_stacktrace, stack} -> + {classify_stack(stack), format_stack(stack)} + + _ -> + {:unknown, "unavailable"} + end + end + + defp classify_stack(stack) do + Enum.find_value(stack, :unknown, fn {module, _fun, _arity, _loc} -> + Map.get(@untrack_sources, module) + end) + end + + # Only frames outside this module, and only a handful: enough to name the + # caller without dumping an entire LiveView stack into the log. Process is + # dropped too — it is the Process.info/2 call that captured the stack, not a + # caller, and it would otherwise head every line. + defp format_stack(stack) do + stack + |> Enum.reject(fn {module, _fun, _arity, _loc} -> + module in [__MODULE__, Process] + end) + |> Enum.take(6) + |> Enum.map_join(" <- ", fn {module, fun, arity, loc} -> + file = loc |> Keyword.get(:file, ~c"?") |> to_string() + line = Keyword.get(loc, :line, 0) + "#{inspect(module)}.#{fun}/#{arity} (#{file}:#{line})" + end) + end + def track!(settings) do case track(settings) do {:ok, result} -> result diff --git a/test/unit/metrics/prom_ex_plugin_test.exs b/test/unit/metrics/prom_ex_plugin_test.exs index 1b8506bfc..56d9b5ce1 100644 --- a/test/unit/metrics/prom_ex_plugin_test.exs +++ b/test/unit/metrics/prom_ex_plugin_test.exs @@ -42,6 +42,7 @@ defmodule WandererApp.Metrics.PromExPluginTest do [:wanderer_app, :character, :tracking, :online_transition, :count], [:wanderer_app, :character, :tracker, :stopped, :count], [:wanderer_app, :character, :tracker, :untracked_from_map, :count], + [:wanderer_app, :map, :character_settings, :untracked, :count], [:wanderer_app, :token, :refresh_failed, :count] ] @@ -184,5 +185,23 @@ defmodule WandererApp.Metrics.PromExPluginTest do time_since_expiry: 12 }) end + + test "the database uncheck is registered and names the code path" do + # Every writer of tracked=false funnels through + # MapCharacterSettingsRepo.untrack/1, so this counter sees an uncheck no + # matter which path caused it. :source is what makes it diagnostic rather + # than just a count. + metric = find!([:wanderer_app, :map, :character_settings, :untracked, :count]) + + assert :source in metric.tags + assert :character_id in metric.tags + + assert %{source: :acl_sweep, character_id: "char-1"} = + metric.tag_values.(%{ + character_id: "char-1", + map_id: "map-1", + source: :acl_sweep + }) + end end end diff --git a/test/unit/repositories/map_character_settings_repo_untrack_test.exs b/test/unit/repositories/map_character_settings_repo_untrack_test.exs new file mode 100644 index 000000000..130c72be8 --- /dev/null +++ b/test/unit/repositories/map_character_settings_repo_untrack_test.exs @@ -0,0 +1,115 @@ +defmodule WandererApp.Repositories.MapCharacterSettingsRepoUntrackTest do + @moduledoc """ + Covers the provenance instrumentation on `MapCharacterSettingsRepo.untrack/1`. + + Users report their tracking box unchecking itself while none of the three + known callers — the UI toggle, the ACL permission sweep, and character + deletion — appears responsible. Every one of them funnels through + `untrack/1`, so it is the single point that can observe an uncheck regardless + of which path caused it, and the `:source` tag is what turns the count into a + diagnosis. + + The transition guard matters as much as the emit: a repeat untrack of an + already-untracked character changes nothing, and counting it would inflate the + metric against the reports it exists to explain. + """ + + use WandererApp.DataCase, async: false + + alias WandererApp.MapCharacterSettingsRepo + + @event [:wanderer_app, :map, :character_settings, :untracked] + + setup do + handler_id = "untrack-test-#{System.unique_integer([:positive])}" + test_pid = self() + + :telemetry.attach( + handler_id, + @event, + fn _event, measurements, metadata, _ -> + send(test_pid, {:telemetry, measurements, metadata}) + end, + nil + ) + + on_exit(fn -> :telemetry.detach(handler_id) end) + :ok + end + + describe "untrack/1 instrumentation" do + test "emits when a tracked character is unchecked" do + %{map_id: map_id, character_id: character_id} = tracked_settings() + + {:ok, _} = MapCharacterSettingsRepo.untrack(%{map_id: map_id, character_id: character_id}) + + assert_receive {:telemetry, %{count: 1}, + %{character_id: ^character_id, map_id: ^map_id, source: source}} + + # Called directly from a test process, so no known caller module appears in + # the stack. :unknown is the honest answer and is exactly the value that + # should prompt a look at the accompanying log line. + assert source == :unknown + end + + test "does not emit when the character was already untracked" do + %{map_id: map_id, character_id: character_id} = tracked_settings() + + {:ok, _} = MapCharacterSettingsRepo.untrack(%{map_id: map_id, character_id: character_id}) + assert_receive {:telemetry, _, _} + + {:ok, _} = MapCharacterSettingsRepo.untrack(%{map_id: map_id, character_id: character_id}) + + refute_receive {:telemetry, _, _}, 200 + end + + test "leaves the character untracked" do + %{map_id: map_id, character_id: character_id} = tracked_settings() + + {:ok, updated} = + MapCharacterSettingsRepo.untrack(%{map_id: map_id, character_id: character_id}) + + assert updated.tracked == false + end + end + + describe "update/3 cannot bypass the instrumentation" do + test "reports an uncheck made through the generic update path" do + %{map_id: map_id, character_id: character_id} = tracked_settings() + + {:ok, _} = MapCharacterSettingsRepo.update(map_id, character_id, %{tracked: false}) + + assert_receive {:telemetry, %{count: 1}, %{character_id: ^character_id, map_id: ^map_id}} + end + + test "does not report when the update leaves tracking alone" do + %{map_id: map_id, character_id: character_id} = tracked_settings() + + {:ok, _} = MapCharacterSettingsRepo.update(map_id, character_id, %{ship_name: "Loki"}) + + refute_receive {:telemetry, _, _}, 200 + end + + test "does not report when the update sets tracking on" do + %{map_id: map_id, character_id: character_id} = tracked_settings() + + {:ok, _} = MapCharacterSettingsRepo.update(map_id, character_id, %{tracked: true}) + + refute_receive {:telemetry, _, _}, 200 + end + end + + defp tracked_settings do + map = WandererAppWeb.Factory.insert(:map, %{}) + character = WandererAppWeb.Factory.insert(:character, %{}) + + {:ok, _settings} = + WandererApp.Api.MapCharacterSettings.create(%{ + map_id: map.id, + character_id: character.id, + tracked: true + }) + + %{map_id: map.id, character_id: character.id} + end +end