fix(tracking): record which code path unchecks a character's tracking box

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

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

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

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