prop/test/microwaveprop_web/metrics_log_suppression_test.exs
Graham McIntire 38ef716a7c
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.
2026-04-21 10:44:25 -05:00

56 lines
2 KiB
Elixir

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