feat(observability): emit telemetry for NotifyListener warm + GridCache hit/miss

Band-warm failures in the Rust propagation_ready pipeline were only
surfaced via Logger.warning, so Prometheus had no way to see them.
The /weather GridCache hit/miss was likewise invisible while its
/map counterpart (ScoreCache) already reported cache ratio.

- NotifyListener emits [:microwaveprop, :propagation, :notify_listener, :warm]
  with %{ok, err} measurements and %{valid_time} metadata after every
  propagation_ready notification. Public handle_propagation_ready/1 so
  tests can exercise the warm+telemetry path without Postgrex.
- GridCache.fetch/1, fetch_bounds/2, and fetch_point/3 emit
  [:microwaveprop, :weather, :grid_cache, :lookup] with a :hit | :miss
  metadata key on every ETS lookup.
This commit is contained in:
Graham McIntire 2026-04-21 13:30:26 -05:00
parent ccf6779fb1
commit b7261e772c
No known key found for this signature in database
GPG key ID: F4ABF488E6029E59
4 changed files with 218 additions and 7 deletions

View file

@ -84,7 +84,14 @@ defmodule Microwaveprop.Propagation.NotifyListener do
end
end
defp handle_propagation_ready(valid_time) do
@doc """
Warm `ScoreCache` for every band at `valid_time`, prune old cache
entries, and broadcast `propagation_updated` to PubSub. Public so
tests can exercise the warm+telemetry path without standing up the
Postgrex.Notifications subscriber.
"""
@spec handle_propagation_ready(DateTime.t()) :: :ok
def handle_propagation_ready(valid_time) do
{ok, err} =
Enum.reduce(BandConfig.all_bands(), {0, 0}, fn band, {ok, err} ->
case warm_band(band.freq_mhz, valid_time) do
@ -93,6 +100,12 @@ defmodule Microwaveprop.Propagation.NotifyListener do
end
end)
:telemetry.execute(
[:microwaveprop, :propagation, :notify_listener, :warm],
%{ok: ok, err: err},
%{valid_time: valid_time}
)
# Prune anything older than 2 hours so the cache doesn't grow
# unbounded when Rust covers many forecast hours back-to-back.
ScoreCache.prune_older_than(DateTime.add(DateTime.utc_now(), -2, :hour))
@ -104,6 +117,8 @@ defmodule Microwaveprop.Propagation.NotifyListener do
else
Logger.info("NotifyListener: warmed ScoreCache + broadcast for valid_time=#{valid_time}")
end
:ok
end
defp warm_band(band_mhz, valid_time) do

View file

@ -32,16 +32,26 @@ defmodule Microwaveprop.Weather.GridCache do
@spec fetch(DateTime.t()) :: {:ok, [row()]} | :miss
def fetch(valid_time) do
case :ets.lookup(@table, valid_time) do
[{_, grid}] -> {:ok, grid_to_list(grid)}
[] -> :miss
[{_, grid}] ->
emit_lookup(true)
{:ok, grid_to_list(grid)}
[] ->
emit_lookup(false)
:miss
end
end
@spec fetch_bounds(DateTime.t(), bounds() | nil) :: {:ok, [row()]} | :miss
def fetch_bounds(valid_time, bounds) do
case :ets.lookup(@table, valid_time) do
[{_, grid}] -> {:ok, grid_to_filtered_list(grid, bounds)}
[] -> :miss
[{_, grid}] ->
emit_lookup(true)
{:ok, grid_to_filtered_list(grid, bounds)}
[] ->
emit_lookup(false)
:miss
end
end
@ -50,15 +60,25 @@ defmodule Microwaveprop.Weather.GridCache do
case :ets.lookup(@table, valid_time) do
[{_, grid}] ->
case Map.get(grid, {lat, lon}) do
nil -> :miss
row -> {:ok, row}
nil ->
emit_lookup(false)
:miss
row ->
emit_lookup(true)
{:ok, row}
end
[] ->
emit_lookup(false)
:miss
end
end
defp emit_lookup(hit) do
:telemetry.execute([:microwaveprop, :weather, :grid_cache, :lookup], %{}, %{hit: hit})
end
@spec put(DateTime.t(), [row()]) :: :ok
def put(valid_time, rows) do
grid = list_to_grid(rows)

View file

@ -0,0 +1,114 @@
defmodule Microwaveprop.Propagation.NotifyListenerTest do
# async: false — uses the shared :propagation_scores_dir + ScoreCache
use ExUnit.Case, async: false
alias Microwaveprop.Propagation.BandConfig
alias Microwaveprop.Propagation.Grid
alias Microwaveprop.Propagation.NotifyListener
alias Microwaveprop.Propagation.ScoreCache
alias Microwaveprop.Propagation.ScoresFile
setup do
dir =
Path.join(
System.tmp_dir!(),
"notify_listener_test_#{System.unique_integer([:positive])}"
)
File.mkdir_p!(dir)
prev = Application.get_env(:microwaveprop, :propagation_scores_dir)
Application.put_env(:microwaveprop, :propagation_scores_dir, dir)
ScoreCache.clear()
on_exit(fn ->
File.rm_rf!(dir)
ScoreCache.clear()
if prev do
Application.put_env(:microwaveprop, :propagation_scores_dir, prev)
else
Application.delete_env(:microwaveprop, :propagation_scores_dir)
end
end)
:ok
end
defp sample_scores do
%{lat_min: lat_min, lon_min: lon_min, lat_max: lat_max, lon_max: lon_max} = Grid.bounds()
[
%{lat: lat_min, lon: lon_min, score: 10},
%{lat: lat_max, lon: lon_max, score: 90}
]
end
describe "handle_propagation_ready/1 telemetry" do
test "emits propagation.notify_listener.warm with ok/err counts after warming every band" do
valid_time = ~U[2026-04-21 12:00:00Z]
# Write a scores file for the first band only so the rest hit :enoent
# and contribute to the err tally. That gives us at least one ok and
# at least one err for an all-bands warm.
[first_band | _rest] = Enum.map(BandConfig.all_bands(), & &1.freq_mhz)
ScoresFile.write!(first_band, valid_time, sample_scores())
total_bands = length(BandConfig.all_bands())
expected_err = total_bands - 1
test_pid = self()
handler_id = {__MODULE__, :notify_listener_warm}
:telemetry.attach(
handler_id,
[:microwaveprop, :propagation, :notify_listener, :warm],
fn event, measurements, metadata, _config ->
send(test_pid, {:telemetry, event, measurements, metadata})
end,
nil
)
try do
:ok = NotifyListener.handle_propagation_ready(valid_time)
event = [:microwaveprop, :propagation, :notify_listener, :warm]
assert_receive {:telemetry, ^event, %{ok: 1, err: ^expected_err}, %{valid_time: ^valid_time}}
after
:telemetry.detach(handler_id)
end
end
test "emits telemetry even when every band warms successfully" do
valid_time = ~U[2026-04-21 13:00:00Z]
for band <- BandConfig.all_bands() do
ScoresFile.write!(band.freq_mhz, valid_time, sample_scores())
end
total_bands = length(BandConfig.all_bands())
test_pid = self()
handler_id = {__MODULE__, :notify_listener_warm_all_ok}
:telemetry.attach(
handler_id,
[:microwaveprop, :propagation, :notify_listener, :warm],
fn event, measurements, metadata, _config ->
send(test_pid, {:telemetry, event, measurements, metadata})
end,
nil
)
try do
:ok = NotifyListener.handle_propagation_ready(valid_time)
event = [:microwaveprop, :propagation, :notify_listener, :warm]
assert_receive {:telemetry, ^event, %{ok: ^total_bands, err: 0}, %{valid_time: ^valid_time}}
after
:telemetry.detach(handler_id)
end
end
end
end

View file

@ -121,6 +121,68 @@ defmodule Microwaveprop.Weather.GridCacheTest do
end
end
describe "lookup telemetry" do
@event [:microwaveprop, :weather, :grid_cache, :lookup]
setup do
test_pid = self()
handler_id = {__MODULE__, :grid_cache_lookup, System.unique_integer([:positive])}
:telemetry.attach(
handler_id,
@event,
fn event, measurements, metadata, _config ->
send(test_pid, {:telemetry, event, measurements, metadata})
end,
nil
)
on_exit(fn -> :telemetry.detach(handler_id) end)
:ok
end
test "fetch/1 emits hit: true when the valid_time is cached" do
GridCache.put(~U[2026-04-12 12:00:00Z], [%{lat: 32.0, lon: -97.0}])
{:ok, _} = GridCache.fetch(~U[2026-04-12 12:00:00Z])
assert_receive {:telemetry, @event, %{}, %{hit: true}}
end
test "fetch/1 emits hit: false when the valid_time is absent" do
:miss = GridCache.fetch(~U[2099-01-01 00:00:00Z])
assert_receive {:telemetry, @event, %{}, %{hit: false}}
end
test "fetch_bounds/2 emits hit: true on a cached valid_time" do
GridCache.put(~U[2026-04-12 12:00:00Z], [%{lat: 32.0, lon: -97.0}])
bounds = %{"south" => 0.0, "north" => 90.0, "west" => -180.0, "east" => 0.0}
{:ok, _} = GridCache.fetch_bounds(~U[2026-04-12 12:00:00Z], bounds)
assert_receive {:telemetry, @event, %{}, %{hit: true}}
end
test "fetch_bounds/2 emits hit: false when the valid_time is absent" do
bounds = %{"south" => 0.0, "north" => 90.0, "west" => -180.0, "east" => 0.0}
:miss = GridCache.fetch_bounds(~U[2099-01-01 00:00:00Z], bounds)
assert_receive {:telemetry, @event, %{}, %{hit: false}}
end
test "fetch_point/3 emits hit: true when the point exists" do
GridCache.put(~U[2026-04-12 12:00:00Z], [%{lat: 32.0, lon: -97.0}])
{:ok, _} = GridCache.fetch_point(~U[2026-04-12 12:00:00Z], 32.0, -97.0)
assert_receive {:telemetry, @event, %{}, %{hit: true}}
end
test "fetch_point/3 emits hit: false when the valid_time is missing" do
:miss = GridCache.fetch_point(~U[2099-01-01 00:00:00Z], 1.0, 2.0)
assert_receive {:telemetry, @event, %{}, %{hit: false}}
end
test "fetch_point/3 emits hit: false when the point is missing from a cached grid" do
GridCache.put(~U[2026-04-12 12:00:00Z], [%{lat: 32.0, lon: -97.0}])
:miss = GridCache.fetch_point(~U[2026-04-12 12:00:00Z], 40.0, -74.0)
assert_receive {:telemetry, @event, %{}, %{hit: false}}
end
end
describe "latest_valid_time/0" do
test "returns the most recent cached valid_time" do
GridCache.put(~U[2026-04-12 10:00:00Z], [])