Graham McIntire
93b526c761
The log_level(%{method: \"HEAD\"}) clause never matched because
Plug.Head rewrites the method to \"GET\" before Plug.Telemetry's
register_before_send callback fires, so by log time conn.method is
\"GET\". Stash the original method in private before Plug.Head runs
and key the filter off it.
102 lines
3.4 KiB
Elixir
102 lines
3.4 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 "GET /live does not emit a Phoenix endpoint Sent log line", %{conn: conn} do
|
|
log =
|
|
capture_log([level: :info], fn ->
|
|
conn = get(conn, "/live")
|
|
assert conn.status == 200
|
|
end)
|
|
|
|
refute log =~ "Sent 200"
|
|
refute log =~ "GET /live"
|
|
end
|
|
|
|
test "log_level/1 returns false for /live", %{conn: _conn} do
|
|
assert MicrowavepropWeb.Endpoint.log_level(%{
|
|
request_path: "/live",
|
|
method: "GET"
|
|
}) == false
|
|
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
|
|
|
|
test "log_level/1 returns false when the original method stashed before Plug.Head was HEAD" do
|
|
# Plug.Head runs BEFORE Plug.Telemetry's register_before_send fires
|
|
# and rewrites HEAD→GET, so matching `method: \"HEAD\"` at log time
|
|
# never hits. Endpoint now stashes the original method in private
|
|
# before Plug.Head runs; assert the filter keys off it.
|
|
conn = %{
|
|
request_path: "/some/page",
|
|
method: "GET",
|
|
private: %{original_method: "HEAD"}
|
|
}
|
|
|
|
assert MicrowavepropWeb.Endpoint.log_level(conn) == false
|
|
end
|
|
|
|
test "HEAD request to a real route does not emit a Phoenix endpoint Sent log line", %{
|
|
conn: conn
|
|
} do
|
|
log =
|
|
capture_log([level: :info], fn ->
|
|
conn = dispatch(conn, MicrowavepropWeb.Endpoint, "HEAD", "/")
|
|
assert conn.status in [200, 302]
|
|
end)
|
|
|
|
refute log =~ "Sent 200"
|
|
refute log =~ "Sent 302"
|
|
refute log =~ "HEAD /"
|
|
end
|
|
end
|