fix(logging): suppress /metrics logs and harden scorer hot path
- endpoint.ex log_level/1 now filters by conn.request_path instead of
conn.path_info. Plug.Router.forward/2 (deps/plug/lib/plug.ex:170)
rewrites path_info to the unmatched remainder and extends script_name
with the matched prefix before dispatching to the forwarded plug.
/metrics is routed via forward "/metrics", MetricsPlug; by the time
Plug.Telemetry's before_send callback fires inside MetricsPlug.call/2
the conn it observes has path_info: [] and script_name: ["metrics"],
so the old log_level(%{path_info: ["metrics" | _]}) clause never
matched and the default :info level fired. request_path is set by
the adapter at entry and is never rewritten, making it the correct
discriminator. New regression test in metrics_log_suppression_test.exs
captures both the direct shape and the integration path via Plug.Test.
- Scorer.dbz_to_rain_rate_mmhr/1 now uses a compile-time @mp_inv_b
constant (1 / 1.6) instead of dividing on every rain pixel.
composite_score/2's band-invariant fallback switched from four
separate short-circuits (which silently
mixed cached and freshly-computed values if only some keys were
passed) to a single Map.has_key?/2 branch that honors the "all or
none" contract. Dropped unused band_invariant_tod/1 helper.
- Propagation.replace_scores span scope tightened: the
Instrument.span([:db, :replace_scores]) now wraps only the per-band
ScoresFile.write! loop, not the upstream Enum.group_by grouping
phase. The span name + metadata stay unchanged so Grafana panels
keep working, but the fixed telemetry dispatch cost (~100µs x 2)
is no longer paid for trivially small result sets.
- Added @type t :: %__MODULE__{...} to Accounts.UserToken and
Weather.HrrrClimatology — the last two schemas that lacked one.
Elixir 1.19's set-theoretic inference benefits from every struct
having an explicit t/0 so callers can flow through tightly.
mix dialyzer --format short | grep ^lib/ | wc -l -> 0
mix test: 2165 tests, 3 pre-existing flakes, 0 new regressions.
This commit is contained in:
parent
6c977e250d
commit
38ef716a7c
6 changed files with 134 additions and 32 deletions
|
|
@ -4,6 +4,7 @@ defmodule Microwaveprop.Accounts.UserToken do
|
||||||
|
|
||||||
import Ecto.Query
|
import Ecto.Query
|
||||||
|
|
||||||
|
alias Microwaveprop.Accounts.User
|
||||||
alias Microwaveprop.Accounts.UserToken
|
alias Microwaveprop.Accounts.UserToken
|
||||||
|
|
||||||
@hash_algorithm :sha256
|
@hash_algorithm :sha256
|
||||||
|
|
@ -24,11 +25,22 @@ defmodule Microwaveprop.Accounts.UserToken do
|
||||||
field :context, :string
|
field :context, :string
|
||||||
field :sent_to, :string
|
field :sent_to, :string
|
||||||
field :authenticated_at, :utc_datetime
|
field :authenticated_at, :utc_datetime
|
||||||
belongs_to :user, Microwaveprop.Accounts.User
|
belongs_to :user, User
|
||||||
|
|
||||||
timestamps(type: :utc_datetime, updated_at: false)
|
timestamps(type: :utc_datetime, updated_at: false)
|
||||||
end
|
end
|
||||||
|
|
||||||
|
@type t :: %__MODULE__{
|
||||||
|
id: Ecto.UUID.t() | nil,
|
||||||
|
token: binary() | nil,
|
||||||
|
context: String.t() | nil,
|
||||||
|
sent_to: String.t() | nil,
|
||||||
|
authenticated_at: DateTime.t() | nil,
|
||||||
|
user: User.t() | Ecto.Association.NotLoaded.t() | nil,
|
||||||
|
user_id: Ecto.UUID.t() | nil,
|
||||||
|
inserted_at: DateTime.t() | nil
|
||||||
|
}
|
||||||
|
|
||||||
@doc """
|
@doc """
|
||||||
Generates a token that will be stored in a signed place,
|
Generates a token that will be stored in a signed place,
|
||||||
such as session or cookie. As they are signed, those
|
such as session or cookie. As they are signed, those
|
||||||
|
|
|
||||||
|
|
@ -172,29 +172,35 @@ defmodule Microwaveprop.Propagation do
|
||||||
"""
|
"""
|
||||||
@spec replace_scores(Enumerable.t(), DateTime.t()) :: {:ok, non_neg_integer()} | {:error, term()}
|
@spec replace_scores(Enumerable.t(), DateTime.t()) :: {:ok, non_neg_integer()} | {:error, term()}
|
||||||
def replace_scores(scores, %DateTime{} = valid_time) do
|
def replace_scores(scores, %DateTime{} = valid_time) do
|
||||||
Microwaveprop.Instrument.span(
|
do_replace_scores(scores, valid_time)
|
||||||
[:db, :replace_scores],
|
|
||||||
%{valid_time: valid_time},
|
|
||||||
fn -> do_replace_scores(scores, valid_time) end
|
|
||||||
)
|
|
||||||
end
|
end
|
||||||
|
|
||||||
defp do_replace_scores(scores, valid_time) do
|
defp do_replace_scores(scores, valid_time) do
|
||||||
|
# Pure grouping phase runs outside the telemetry span — typically
|
||||||
|
# <10ms on small result sets, and the span's two dispatches
|
||||||
|
# (~100µs each) would otherwise dominate. The span now wraps only
|
||||||
|
# the per-band writes, which is where the actual DB cost lives.
|
||||||
{per_band, total} =
|
{per_band, total} =
|
||||||
Enum.reduce(scores, {%{}, 0}, fn score, {acc, count} ->
|
Enum.reduce(scores, {%{}, 0}, fn score, {acc, count} ->
|
||||||
{Map.update(acc, score.band_mhz, [score], &[score | &1]), count + 1}
|
{Map.update(acc, score.band_mhz, [score], &[score | &1]), count + 1}
|
||||||
end)
|
end)
|
||||||
|
|
||||||
Enum.each(per_band, fn {band_mhz, band_scores} ->
|
Microwaveprop.Instrument.span(
|
||||||
try do
|
[:db, :replace_scores],
|
||||||
ScoresFile.write!(band_mhz, valid_time, band_scores)
|
%{valid_time: valid_time},
|
||||||
rescue
|
fn ->
|
||||||
e ->
|
Enum.each(per_band, fn {band_mhz, band_scores} ->
|
||||||
Logger.warning("Propagation: ScoresFile write failed for band=#{band_mhz} vt=#{valid_time}: #{inspect(e)}")
|
try do
|
||||||
end
|
ScoresFile.write!(band_mhz, valid_time, band_scores)
|
||||||
end)
|
rescue
|
||||||
|
e ->
|
||||||
|
Logger.warning("Propagation: ScoresFile write failed for band=#{band_mhz} vt=#{valid_time}: #{inspect(e)}")
|
||||||
|
end
|
||||||
|
end)
|
||||||
|
|
||||||
{:ok, total}
|
{:ok, total}
|
||||||
|
end
|
||||||
|
)
|
||||||
end
|
end
|
||||||
|
|
||||||
@doc """
|
@doc """
|
||||||
|
|
|
||||||
|
|
@ -12,6 +12,11 @@ defmodule Microwaveprop.Propagation.Scorer do
|
||||||
# ── Temperature conversion helpers ────────────────────────────────
|
# ── Temperature conversion helpers ────────────────────────────────
|
||||||
alias Microwaveprop.Propagation.Region
|
alias Microwaveprop.Propagation.Region
|
||||||
|
|
||||||
|
# Compile-time inverse of the Marshall-Palmer b exponent (1/1.6).
|
||||||
|
# Pre-computed to avoid one float division per rain pixel in the
|
||||||
|
# dBZ → rain-rate hot path.
|
||||||
|
@mp_inv_b 1 / 1.6
|
||||||
|
|
||||||
@doc "Converts Fahrenheit to Celsius. Returns nil for nil input."
|
@doc "Converts Fahrenheit to Celsius. Returns nil for nil input."
|
||||||
@spec f_to_c(number() | nil) :: float() | nil
|
@spec f_to_c(number() | nil) :: float() | nil
|
||||||
def f_to_c(nil), do: nil
|
def f_to_c(nil), do: nil
|
||||||
|
|
@ -67,7 +72,7 @@ defmodule Microwaveprop.Propagation.Scorer do
|
||||||
|
|
||||||
def dbz_to_rain_rate_mmhr(dbz) do
|
def dbz_to_rain_rate_mmhr(dbz) do
|
||||||
z = :math.pow(10, dbz / 10)
|
z = :math.pow(10, dbz / 10)
|
||||||
r = :math.pow(z / 200, 1 / 1.6)
|
r = :math.pow(z / 200, @mp_inv_b)
|
||||||
min(r, 150.0)
|
min(r, 150.0)
|
||||||
end
|
end
|
||||||
|
|
||||||
|
|
@ -522,12 +527,22 @@ defmodule Microwaveprop.Propagation.Scorer do
|
||||||
"""
|
"""
|
||||||
@spec composite_score(map(), map()) :: %{score: integer(), factors: map()}
|
@spec composite_score(map(), map()) :: %{score: integer(), factors: map()}
|
||||||
def composite_score(conditions, band_config) do
|
def composite_score(conditions, band_config) do
|
||||||
tod_score = conditions[:tod_score] || band_invariant_tod(conditions)
|
# Contract: band invariants are either all precomputed (via
|
||||||
sky_score = conditions[:sky_score] || score_sky(conditions.sky_cover_pct)
|
# `precompute_band_invariants/1`, typically merged in by the grid
|
||||||
wind_score = conditions[:wind_score] || score_wind(conditions.wind_speed_kts)
|
# scorer for per-point reuse across bands) or all absent. We check
|
||||||
|
# one key and derive the rest from the same branch so we never
|
||||||
pressure_score =
|
# silently mix cached and freshly-computed values.
|
||||||
conditions[:pressure_score] || score_pressure(conditions.pressure_mb, conditions.prev_pressure_mb)
|
%{
|
||||||
|
tod_score: tod_score,
|
||||||
|
sky_score: sky_score,
|
||||||
|
wind_score: wind_score,
|
||||||
|
pressure_score: pressure_score
|
||||||
|
} =
|
||||||
|
if Map.has_key?(conditions, :tod_score) do
|
||||||
|
conditions
|
||||||
|
else
|
||||||
|
precompute_band_invariants(conditions)
|
||||||
|
end
|
||||||
|
|
||||||
factors = %{
|
factors = %{
|
||||||
humidity: score_humidity(conditions.abs_humidity, band_config),
|
humidity: score_humidity(conditions.abs_humidity, band_config),
|
||||||
|
|
@ -559,13 +574,6 @@ defmodule Microwaveprop.Propagation.Scorer do
|
||||||
%{score: round(weighted_sum), factors: factors}
|
%{score: round(weighted_sum), factors: factors}
|
||||||
end
|
end
|
||||||
|
|
||||||
defp band_invariant_tod(conditions) do
|
|
||||||
{s, _} =
|
|
||||||
score_time_of_day(conditions.utc_hour, conditions.utc_minute, conditions.month, conditions.longitude)
|
|
||||||
|
|
||||||
s
|
|
||||||
end
|
|
||||||
|
|
||||||
@doc """
|
@doc """
|
||||||
Merges multiple HRRR profiles along a path into a single conditions map.
|
Merges multiple HRRR profiles along a path into a single conditions map.
|
||||||
|
|
||||||
|
|
|
||||||
|
|
@ -27,7 +27,18 @@ defmodule Microwaveprop.Weather.HrrrClimatology do
|
||||||
field :sample_count, :integer
|
field :sample_count, :integer
|
||||||
end
|
end
|
||||||
|
|
||||||
@spec changeset(%__MODULE__{}, map()) :: Ecto.Changeset.t()
|
@type t :: %__MODULE__{
|
||||||
|
id: Ecto.UUID.t() | nil,
|
||||||
|
lat: float() | nil,
|
||||||
|
lon: float() | nil,
|
||||||
|
month: 1..12 | nil,
|
||||||
|
hour: 0..23 | nil,
|
||||||
|
mean_surface_temp_c: float() | nil,
|
||||||
|
stddev_surface_temp_c: float() | nil,
|
||||||
|
sample_count: non_neg_integer() | nil
|
||||||
|
}
|
||||||
|
|
||||||
|
@spec changeset(t(), map()) :: Ecto.Changeset.t()
|
||||||
def changeset(record, attrs) do
|
def changeset(record, attrs) do
|
||||||
record
|
record
|
||||||
|> cast(attrs, [:lat, :lon, :month, :hour, :mean_surface_temp_c, :stddev_surface_temp_c, :sample_count])
|
|> cast(attrs, [:lat, :lon, :month, :hour, :mean_surface_temp_c, :stddev_surface_temp_c, :sample_count])
|
||||||
|
|
|
||||||
|
|
@ -59,8 +59,17 @@ defmodule MicrowavepropWeb.Endpoint do
|
||||||
plug MicrowavepropWeb.Router
|
plug MicrowavepropWeb.Router
|
||||||
|
|
||||||
@doc false
|
@doc false
|
||||||
def log_level(%{path_info: ["health"]}), do: false
|
# Match on `request_path` rather than `path_info` because `Plug.forward/4`
|
||||||
def log_level(%{path_info: ["metrics" | _]}), do: false
|
# (used by `forward "/metrics", MetricsPlug` in the router) rewrites
|
||||||
|
# `path_info` to the unmatched remainder before dispatching to the
|
||||||
|
# forwarded plug. `MetricsPlug` calls `send_resp/2` inside that
|
||||||
|
# dispatch, so `Plug.Telemetry`'s `register_before_send` callback sees
|
||||||
|
# `path_info: []` / `script_name: ["metrics"]` and a clause keyed on
|
||||||
|
# `path_info` never matches. `request_path` is set once by the adapter
|
||||||
|
# and is stable across forward, so it's the reliable discriminator.
|
||||||
|
def log_level(%{request_path: "/health"}), do: false
|
||||||
|
def log_level(%{request_path: "/metrics"}), do: false
|
||||||
|
def log_level(%{request_path: "/metrics/" <> _}), do: false
|
||||||
def log_level(%{method: "HEAD"}), do: false
|
def log_level(%{method: "HEAD"}), do: false
|
||||||
def log_level(_conn), do: :info
|
def log_level(_conn), do: :info
|
||||||
end
|
end
|
||||||
|
|
|
||||||
56
test/microwaveprop_web/metrics_log_suppression_test.exs
Normal file
56
test/microwaveprop_web/metrics_log_suppression_test.exs
Normal file
|
|
@ -0,0 +1,56 @@
|
||||||
|
defmodule MicrowavepropWeb.MetricsLogSuppressionTest do
|
||||||
|
@moduledoc """
|
||||||
|
Regression test for the `/metrics` log-suppression bug.
|
||||||
|
|
||||||
|
`Plug.forward/4` rewrites `conn.path_info` to the remainder after the
|
||||||
|
matched prefix before dispatching to the forwarded plug. For the
|
||||||
|
`forward "/metrics", MetricsPlug` route this means `path_info` is `[]`
|
||||||
|
(and `script_name` is `["metrics"]`) by the time the response is being
|
||||||
|
sent. Since `send_resp/2` runs inside the forwarded plug, the
|
||||||
|
`register_before_send` callback installed by `Plug.Telemetry` sees the
|
||||||
|
rewritten conn and the endpoint's `log_level/1` pattern on
|
||||||
|
`path_info: ["metrics" | _]` never matches — so a `Sent 200 in Xms`
|
||||||
|
line is logged on every Prometheus scrape.
|
||||||
|
"""
|
||||||
|
|
||||||
|
use MicrowavepropWeb.ConnCase, async: false
|
||||||
|
|
||||||
|
import ExUnit.CaptureLog
|
||||||
|
|
||||||
|
setup do
|
||||||
|
# The project config sets :logger level to :warning in test, which
|
||||||
|
# would drop the :info-level "Sent 200" line before capture_log ever
|
||||||
|
# saw it. Bump to :info for this test so the suppression behaviour
|
||||||
|
# is actually observable, then restore afterwards.
|
||||||
|
prev_level = Logger.level()
|
||||||
|
Logger.configure(level: :info)
|
||||||
|
on_exit(fn -> Logger.configure(level: prev_level) end)
|
||||||
|
:ok
|
||||||
|
end
|
||||||
|
|
||||||
|
test "GET /metrics does not emit a Phoenix endpoint Sent log line", %{conn: conn} do
|
||||||
|
log =
|
||||||
|
capture_log([level: :info], fn ->
|
||||||
|
conn = get(conn, "/metrics")
|
||||||
|
assert conn.status == 200
|
||||||
|
end)
|
||||||
|
|
||||||
|
refute log =~ "Sent 200"
|
||||||
|
end
|
||||||
|
|
||||||
|
test "log_level/1 returns false for the rewritten conn shape produced by forward", %{
|
||||||
|
conn: _conn
|
||||||
|
} do
|
||||||
|
# When Plug.forward dispatches to the MetricsPlug, the conn it passes
|
||||||
|
# has path_info stripped (empty) and script_name holding the prefix.
|
||||||
|
# Plug.Telemetry's before_send sees this exact shape.
|
||||||
|
rewritten = %{
|
||||||
|
path_info: [],
|
||||||
|
script_name: ["metrics"],
|
||||||
|
request_path: "/metrics",
|
||||||
|
method: "GET"
|
||||||
|
}
|
||||||
|
|
||||||
|
assert MicrowavepropWeb.Endpoint.log_level(rewritten) == false
|
||||||
|
end
|
||||||
|
end
|
||||||
Loading…
Add table
Reference in a new issue