From 1778ce5b8471c53a10e0d83e781bfcb442431f73 Mon Sep 17 00:00:00 2001 From: Rodrigo Caldeira Date: Thu, 19 Sep 2024 21:49:24 -0300 Subject: [PATCH 1/6] Initial Bandit integration --- lib/new_relic/telemetry/plug.ex | 122 +++++++++++++++++++++++++++++--- 1 file changed, 113 insertions(+), 9 deletions(-) diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex index 70f443c3..5895ded1 100644 --- a/lib/new_relic/telemetry/plug.ex +++ b/lib/new_relic/telemetry/plug.ex @@ -53,6 +53,9 @@ defmodule NewRelic.Telemetry.Plug do @cowboy_start [:cowboy, :request, :start] @cowboy_stop [:cowboy, :request, :stop] @cowboy_exception [:cowboy, :request, :exception] + @bandit_start [:bandit, :request, :start] + @bandit_stop [:bandit, :request, :stop] + @bandit_exception [:bandit, :request, :exception] @plug_router_start [:plug, :router_dispatch, :start] @@ -60,7 +63,10 @@ defmodule NewRelic.Telemetry.Plug do @cowboy_start, @cowboy_stop, @cowboy_exception, - @plug_router_start + @plug_router_start, + @bandit_start, + @bandit_stop, + @bandit_exception ] @doc false @@ -95,8 +101,8 @@ defmodule NewRelic.Telemetry.Plug do if NewRelic.Config.enabled?(), do: DistributedTrace.start(:http, meta.req.headers) - add_start_attrs(meta, system_time) - maybe_report_queueing(meta) + add_start_attrs(meta, system_time, :cowboy) + maybe_report_queueing(meta, :cowboy) end def handle_event( @@ -114,7 +120,7 @@ defmodule NewRelic.Telemetry.Plug do meta, _config ) do - add_stop_attrs(meas, meta, duration) + add_stop_attrs(meas, meta, duration, :cowboy) add_stop_error_attrs(meta) Transaction.Reporter.stop_transaction(:web) @@ -127,7 +133,7 @@ defmodule NewRelic.Telemetry.Plug do %{resp_status: "404" <> _} = meta, _config ) do - add_stop_attrs(meas, meta, duration) + add_stop_attrs(meas, meta, duration, :cowboy) Transaction.Reporter.stop_transaction(:web) end @@ -138,7 +144,59 @@ defmodule NewRelic.Telemetry.Plug do %{kind: kind} = meta, _config ) do - add_stop_attrs(meas, meta, duration) + add_stop_attrs(meas, meta, duration, :cowboy) + {reason, stack} = reason_and_stack(meta) + + Transaction.Reporter.fail(%{kind: kind, reason: reason, stack: stack}) + Transaction.Reporter.stop_transaction(:web) + end + + def handle_event( + @bandit_start, + %{monotonic_time: monotonic_time}, + meta, + _config + ) do + + Transaction.Reporter.start_transaction(:web) + + if NewRelic.Config.enabled?(), + do: DistributedTrace.start(:http, Map.new(meta.conn.req_headers)) + + add_start_attrs(meta, monotonic_time, :bandit) + maybe_report_queueing(meta, :bandit) + end + + def handle_event( + @bandit_stop, + %{duration: duration} = meas, + meta, + _config + ) do + add_stop_attrs(meas, meta, duration, :bandit) + add_stop_error_attrs(meta) + + Transaction.Reporter.stop_transaction(:web) + end + + def handle_event( + @bandit_exception, + %{duration: duration} = meas, + %{resp_status: "404" <> _} = meta, + _config + ) do + add_stop_attrs(meas, meta, duration, :bandit) + + Transaction.Reporter.stop_transaction(:web) + end + + def handle_event( + @bandit_exception, + %{duration: duration} = meas, + %{kind: kind} = meta, + _config + ) do + add_stop_attrs(meas, meta, duration, :bandit) {reason, stack} = reason_and_stack(meta) Transaction.Reporter.fail(%{kind: kind, reason: reason, stack: stack}) @@ -149,7 +207,7 @@ defmodule NewRelic.Telemetry.Plug do :ignore end - defp add_start_attrs(meta, system_time) do + defp add_start_attrs(meta, system_time, :cowboy) do [ pid: inspect(self()), system_time: system_time, @@ -164,8 +222,25 @@ defmodule NewRelic.Telemetry.Plug do |> NewRelic.add_attributes() end + defp add_start_attrs(meta, system_time, :bandit) do + headers = Map.new(meta.conn.req_headers) + [ + pid: inspect(self()), + system_time: system_time, + host: meta.conn.host, + path: meta.conn.request_path, + remote_ip: meta.conn.remote_ip |> :inet_parse.ntoa() |> to_string(), + referer: headers["referer"], + user_agent: headers["user-agent"], + content_type: headers["content-type"], + request_method: meta.conn.method + ] + |> NewRelic.add_attributes() + end + @kb 1024 - defp add_stop_attrs(meas, meta, duration) do + + defp add_stop_attrs(meas, meta, duration, :cowboy) do info = Process.info(self(), [:memory, :reductions]) [ @@ -181,6 +256,21 @@ defmodule NewRelic.Telemetry.Plug do |> NewRelic.add_attributes() end + defp add_stop_attrs(meas, meta, duration, :bandit) do + info = Process.info(self(), [:memory, :reductions]) + + [ + duration: duration, + status: status_code(meta), + memory_kb: info[:memory] / @kb, + reductions: info[:reductions], + "bandit.monotonic_time": meas[:monotonic_time] |> to_ms, + "bandit.resp_duration_ms": (meas[:resp_start_time] |> to_ms) - (meas[:resp_end_time] |> to_ms), + "bandit.resp_body_bytes": meas[:resp_body_bytes] + ] + |> NewRelic.add_attributes() + end + defp add_stop_error_attrs(%{resp_status: "5" <> _, error: {:socket_error, error, message}}) do [ error: true, @@ -216,7 +306,7 @@ defmodule NewRelic.Telemetry.Plug do do: System.convert_time_unit(duration, :native, :microsecond) / 1000 @request_start_header "x-request-start" - defp maybe_report_queueing(meta) do + defp maybe_report_queueing(meta, :cowboy) do with true <- NewRelic.Config.feature?(:request_queuing_metrics), request_start when is_binary(request_start) <- meta.req.headers[@request_start_header], {:ok, request_start_s} <- Util.RequestStart.parse(request_start) do @@ -224,6 +314,16 @@ defmodule NewRelic.Telemetry.Plug do end end + defp maybe_report_queueing(meta, :bandit) do + headers = Map.new(meta.conn.req_headers) + + with true <- NewRelic.Config.feature?(:request_queuing_metrics), + request_start when is_binary(request_start) <- headers[@request_start_header], + {:ok, request_start_s} <- Util.RequestStart.parse(request_start) do + NewRelic.add_attributes(request_start_s: request_start_s) + end + end + defp status_code(%{resp_status: :undefined}) do nil end @@ -238,6 +338,10 @@ defmodule NewRelic.Telemetry.Plug do String.split(status) |> List.first() |> String.to_integer() end + defp status_code(%{conn: %{status: status}}) do + status + end + defp reason_and_stack(%{reason: %{__exception__: true} = reason, stacktrace: stack}) do {reason, stack} end From a184547df59b798f4313ef26a4ccda852843f67e Mon Sep 17 00:00:00 2001 From: Rodrigo Caldeira Date: Wed, 25 Sep 2024 08:06:28 -0300 Subject: [PATCH 2/6] applies sgessa changes suggestions --- lib/new_relic/telemetry/plug.ex | 97 +++++++++------------------------ 1 file changed, 25 insertions(+), 72 deletions(-) diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex index 5895ded1..73549199 100644 --- a/lib/new_relic/telemetry/plug.ex +++ b/lib/new_relic/telemetry/plug.ex @@ -91,18 +91,20 @@ defmodule NewRelic.Telemetry.Plug do @doc false def handle_event( - @cowboy_start, - %{system_time: system_time}, + [server, :request, :start], + measurements, meta, _config ) do Transaction.Reporter.start_transaction(:web) + system_time = get_system_time(measurements) + if NewRelic.Config.enabled?(), - do: DistributedTrace.start(:http, meta.req.headers) + do: DistributedTrace.start(:http, get_headers(meta, server)) - add_start_attrs(meta, system_time, :cowboy) - maybe_report_queueing(meta, :cowboy) + add_start_attrs(meta, system_time, server) + maybe_report_queueing(meta, server) end def handle_event( @@ -115,12 +117,12 @@ defmodule NewRelic.Telemetry.Plug do end def handle_event( - @cowboy_stop, + [server, :request, :stop], %{duration: duration} = meas, meta, _config ) do - add_stop_attrs(meas, meta, duration, :cowboy) + add_stop_attrs(meas, meta, duration, server) add_stop_error_attrs(meta) Transaction.Reporter.stop_transaction(:web) @@ -128,75 +130,23 @@ defmodule NewRelic.Telemetry.Plug do # Don't treat 404 as an exception def handle_event( - @cowboy_exception, - %{duration: duration} = meas, - %{resp_status: "404" <> _} = meta, - _config - ) do - add_stop_attrs(meas, meta, duration, :cowboy) - - Transaction.Reporter.stop_transaction(:web) - end - - def handle_event( - @cowboy_exception, - %{duration: duration} = meas, - %{kind: kind} = meta, - _config - ) do - add_stop_attrs(meas, meta, duration, :cowboy) - {reason, stack} = reason_and_stack(meta) - - Transaction.Reporter.fail(%{kind: kind, reason: reason, stack: stack}) - Transaction.Reporter.stop_transaction(:web) - end - - def handle_event( - @bandit_start, - %{monotonic_time: monotonic_time}, - meta, - _config - ) do - - Transaction.Reporter.start_transaction(:web) - - if NewRelic.Config.enabled?(), - do: DistributedTrace.start(:http, Map.new(meta.conn.req_headers)) - - add_start_attrs(meta, monotonic_time, :bandit) - maybe_report_queueing(meta, :bandit) - end - - def handle_event( - @bandit_stop, - %{duration: duration} = meas, - meta, - _config - ) do - add_stop_attrs(meas, meta, duration, :bandit) - add_stop_error_attrs(meta) - - Transaction.Reporter.stop_transaction(:web) - end - - def handle_event( - @bandit_exception, + [server, :request, :exception], %{duration: duration} = meas, %{resp_status: "404" <> _} = meta, _config ) do - add_stop_attrs(meas, meta, duration, :bandit) + add_stop_attrs(meas, meta, duration, server) Transaction.Reporter.stop_transaction(:web) end def handle_event( - @bandit_exception, + [server, :request, :exception], %{duration: duration} = meas, %{kind: kind} = meta, _config ) do - add_stop_attrs(meas, meta, duration, :bandit) + add_stop_attrs(meas, meta, duration, server) {reason, stack} = reason_and_stack(meta) Transaction.Reporter.fail(%{kind: kind, reason: reason, stack: stack}) @@ -306,22 +256,25 @@ defmodule NewRelic.Telemetry.Plug do do: System.convert_time_unit(duration, :native, :microsecond) / 1000 @request_start_header "x-request-start" - defp maybe_report_queueing(meta, :cowboy) do + defp maybe_report_queueing(meta, server) do + headers = get_headers(meta, server) + with true <- NewRelic.Config.feature?(:request_queuing_metrics), - request_start when is_binary(request_start) <- meta.req.headers[@request_start_header], + request_start when is_binary(request_start) <- headers[@request_start_header], {:ok, request_start_s} <- Util.RequestStart.parse(request_start) do NewRelic.add_attributes(request_start_s: request_start_s) end end - defp maybe_report_queueing(meta, :bandit) do - headers = Map.new(meta.conn.req_headers) + defp get_system_time(%{system_time: system_time}), do: system_time + defp get_system_time(%{monotonic_time: monotonic_time}), do: monotonic_time - with true <- NewRelic.Config.feature?(:request_queuing_metrics), - request_start when is_binary(request_start) <- headers[@request_start_header], - {:ok, request_start_s} <- Util.RequestStart.parse(request_start) do - NewRelic.add_attributes(request_start_s: request_start_s) - end + defp get_headers(meta, :bandit) do + Map.new(meta.conn.req_headers) + end + + defp get_headers(meta, :cowboy) do + meta.req.headers end defp status_code(%{resp_status: :undefined}) do From 75c0d61a3e02c7aef2cbdfd9f48a91924c10b4e9 Mon Sep 17 00:00:00 2001 From: Rodrigo Caldeira Date: Fri, 4 Oct 2024 09:11:39 -0300 Subject: [PATCH 3/6] removes bandit.monotonic_time report --- lib/new_relic/telemetry/plug.ex | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex index 73549199..61187f27 100644 --- a/lib/new_relic/telemetry/plug.ex +++ b/lib/new_relic/telemetry/plug.ex @@ -214,7 +214,6 @@ defmodule NewRelic.Telemetry.Plug do status: status_code(meta), memory_kb: info[:memory] / @kb, reductions: info[:reductions], - "bandit.monotonic_time": meas[:monotonic_time] |> to_ms, "bandit.resp_duration_ms": (meas[:resp_start_time] |> to_ms) - (meas[:resp_end_time] |> to_ms), "bandit.resp_body_bytes": meas[:resp_body_bytes] ] From e076e1b885a3debfde69837d36de1a12fc72c06b Mon Sep 17 00:00:00 2001 From: Rodrigo Caldeira Date: Fri, 4 Oct 2024 09:12:29 -0300 Subject: [PATCH 4/6] fixes formatting --- lib/new_relic/telemetry/plug.ex | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex index 61187f27..85d84f05 100644 --- a/lib/new_relic/telemetry/plug.ex +++ b/lib/new_relic/telemetry/plug.ex @@ -174,6 +174,7 @@ defmodule NewRelic.Telemetry.Plug do defp add_start_attrs(meta, system_time, :bandit) do headers = Map.new(meta.conn.req_headers) + [ pid: inspect(self()), system_time: system_time, @@ -214,7 +215,8 @@ defmodule NewRelic.Telemetry.Plug do status: status_code(meta), memory_kb: info[:memory] / @kb, reductions: info[:reductions], - "bandit.resp_duration_ms": (meas[:resp_start_time] |> to_ms) - (meas[:resp_end_time] |> to_ms), + "bandit.resp_duration_ms": + (meas[:resp_start_time] |> to_ms) - (meas[:resp_end_time] |> to_ms), "bandit.resp_body_bytes": meas[:resp_body_bytes] ] |> NewRelic.add_attributes() From 8d3f1dff574aa9eb19bf50f64e488815c9927846 Mon Sep 17 00:00:00 2001 From: Rodrigo Caldeira Date: Fri, 4 Oct 2024 09:23:33 -0300 Subject: [PATCH 5/6] changes docker-compose command to docker compose --- .github/workflows/elixir.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/elixir.yml b/.github/workflows/elixir.yml index 7eef6264..b8c996c1 100644 --- a/.github/workflows/elixir.yml +++ b/.github/workflows/elixir.yml @@ -139,7 +139,7 @@ jobs: - name: Start integration test dependencies run: | - docker-compose up -d + docker compose up -d until pg_isready -h localhost; do sleep 1; done; until mysqladmin --protocol tcp ping; do sleep 1; done; From e186642bc0bf4bbcfa57ec99b33505ac67dc9884 Mon Sep 17 00:00:00 2001 From: Vince Foley Date: Wed, 9 Oct 2024 12:13:25 -0700 Subject: [PATCH 6/6] Testing and fixes --- examples/apps/phx_example/config/config.exs | 10 + .../lib/phx_example/application.ex | 4 +- .../lib/phx_example_web/bandit_endpoint.ex | 31 +++ examples/apps/phx_example/mix.exs | 3 +- .../phx_example/test/phx_example_test.exs | 198 ++++++++++-------- .../apps/test_support/lib/test_support.ex | 2 +- examples/mix.lock | 3 + lib/new_relic/sampler/beam.ex | 3 +- lib/new_relic/telemetry/plug.ex | 66 +++--- 9 files changed, 189 insertions(+), 131 deletions(-) create mode 100644 examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex diff --git a/examples/apps/phx_example/config/config.exs b/examples/apps/phx_example/config/config.exs index d55cab55..895f68de 100644 --- a/examples/apps/phx_example/config/config.exs +++ b/examples/apps/phx_example/config/config.exs @@ -10,6 +10,16 @@ config :phx_example, PhxExampleWeb.Endpoint, live_view: [signing_salt: "dB7qn7EQ"], secret_key_base: "A+gtEDayUNx4ZyfHvUKETwRC4RjxK0FDlrLjuRhaBnr3Ll3ynfu5RlSSGe5E7zbW" +config :phx_example, PhxExampleWeb.BanditEndpoint, + url: [host: "localhost"], + render_errors: [formats: [html: PhxExampleWeb.ErrorHTML], layout: false], + http: [port: 4005], + server: true, + adapter: Bandit.PhoenixAdapter, + pubsub_server: PhxExample.PubSub, + live_view: [signing_salt: "dB7qn7EQ"], + secret_key_base: "A+gtEDayUNx4ZyfHvUKETwRC4RjxK0FDlrLjuRhaBnr3Ll3ynfu5RlSSGe5E7zbW" + config :logger, level: :warning config :phoenix, :json_library, Jason diff --git a/examples/apps/phx_example/lib/phx_example/application.ex b/examples/apps/phx_example/lib/phx_example/application.ex index 6cb54e84..b8732e82 100644 --- a/examples/apps/phx_example/lib/phx_example/application.ex +++ b/examples/apps/phx_example/lib/phx_example/application.ex @@ -6,7 +6,8 @@ defmodule PhxExample.Application do def start(_type, _args) do children = [ {Phoenix.PubSub, name: PhxExample.PubSub}, - PhxExampleWeb.Endpoint + PhxExampleWeb.Endpoint, + PhxExampleWeb.BanditEndpoint ] opts = [strategy: :one_for_one, name: PhxExample.Supervisor] @@ -15,6 +16,7 @@ defmodule PhxExample.Application do def config_change(changed, _new, removed) do PhxExampleWeb.Endpoint.config_change(changed, removed) + PhxExampleWeb.BanditEndpoint.config_change(changed, removed) :ok end end diff --git a/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex b/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex new file mode 100644 index 00000000..0ee600f9 --- /dev/null +++ b/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex @@ -0,0 +1,31 @@ +defmodule PhxExampleWeb.BanditEndpoint do + use Phoenix.Endpoint, otp_app: :phx_example + + @session_options [ + store: :cookie, + key: "_phx_example_key", + signing_salt: "F6n7gjjvL6I61gUB", + same_site: "Lax" + ] + + socket "/live", Phoenix.LiveView.Socket, websocket: [connect_info: [session: @session_options]] + + plug Plug.Static, + at: "/", + from: :phx_example, + gzip: false, + only: PhxExampleWeb.static_paths() + + plug Plug.RequestId + plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint] + + plug Plug.Parsers, + parsers: [:urlencoded, :multipart, :json], + pass: ["*/*"], + json_decoder: Phoenix.json_library() + + plug Plug.MethodOverride + plug Plug.Head + plug Plug.Session, @session_options + plug PhxExampleWeb.Router +end diff --git a/examples/apps/phx_example/mix.exs b/examples/apps/phx_example/mix.exs index 32b73896..bc80fa82 100644 --- a/examples/apps/phx_example/mix.exs +++ b/examples/apps/phx_example/mix.exs @@ -31,7 +31,8 @@ defmodule PhxExample.MixProject do {:phoenix_view, "~> 2.0"}, {:phoenix_live_view, "~> 0.20"}, {:jason, "~> 1.0"}, - {:plug_cowboy, "~> 2.0"} + {:plug_cowboy, "~> 2.0"}, + {:bandit, "~> 1.0"} ] end end diff --git a/examples/apps/phx_example/test/phx_example_test.exs b/examples/apps/phx_example/test/phx_example_test.exs index fb623dcd..ceffe09e 100644 --- a/examples/apps/phx_example/test/phx_example_test.exs +++ b/examples/apps/phx_example/test/phx_example_test.exs @@ -5,133 +5,145 @@ defmodule PhxExampleTest do setup_all context, do: TestSupport.simulate_agent_enabled(context) - test "Phoenix metrics generated" do - TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) + for server <- [:cowboy, :bandit] do + describe "Testing #{server}:" do + test "Phoenix metrics generated" do + TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body}} = request("/phx/bar") - assert body =~ "Welcome to Phoenix" + {:ok, %{body: body}} = request("/phx/bar", unquote(server)) + assert body =~ "Welcome to Phoenix" - metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) + metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) - assert TestSupport.find_metric( - metrics, - "WebTransaction/Phoenix/PhxExampleWeb.PageController/index" - ) + assert TestSupport.find_metric( + metrics, + "WebTransaction/Phoenix/PhxExampleWeb.PageController/index" + ) - [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) + [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) - assert event[:"phoenix.endpoint"] == "PhxExampleWeb.Endpoint" - assert event[:"phoenix.router"] == "PhxExampleWeb.Router" - assert event[:"phoenix.controller"] == "PhxExampleWeb.PageController" - assert event[:"phoenix.action"] == "index" - assert event[:status] == 200 - end + assert event[:"phoenix.endpoint"] =~ "PhxExampleWeb" + assert event[:"phoenix.router"] == "PhxExampleWeb.Router" + assert event[:"phoenix.controller"] == "PhxExampleWeb.PageController" + assert event[:"phoenix.action"] == "index" + assert event[:status] == 200 + end - test "Phoenix metrics generated for LiveView" do - TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) + test "Phoenix metrics generated for LiveView" do + TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body}} = request("/phx/home") - assert body =~ "Some content" + {:ok, %{body: body}} = request("/phx/home", unquote(server)) + assert body =~ "Some content" - metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) + metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) - assert TestSupport.find_metric( - metrics, - "WebTransaction/Phoenix/PhxExampleWeb.HomeLive/index" - ) + assert TestSupport.find_metric( + metrics, + "WebTransaction/Phoenix/PhxExampleWeb.HomeLive/index" + ) - [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) + [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) - assert event[:"phoenix.endpoint"] == "PhxExampleWeb.Endpoint" - assert event[:"phoenix.router"] == "PhxExampleWeb.Router" - assert event[:"phoenix.controller"] == "Phoenix.LiveView.Plug" - assert event[:"phoenix.action"] == "index" - assert event[:status] == 200 - end + assert event[:"phoenix.endpoint"] =~ "PhxExampleWeb" + assert event[:"phoenix.router"] == "PhxExampleWeb.Router" + assert event[:"phoenix.controller"] == "Phoenix.LiveView.Plug" + assert event[:"phoenix.action"] == "index" + assert event[:status] == 200 + end - @tag :capture_log - test "Phoenix error" do - TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) + @tag :capture_log + test "Phoenix error" do + TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body, status_code: 500}} = request("/phx/error") + {:ok, %{body: body, status_code: 500}} = request("/phx/error", unquote(server)) - assert body =~ "Oops, Internal Server Error" + assert body =~ "Oops, Internal Server Error" - metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) + metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) - assert TestSupport.find_metric( - metrics, - "WebTransaction/Phoenix/PhxExampleWeb.PageController/error" - ) + assert TestSupport.find_metric( + metrics, + "WebTransaction/Phoenix/PhxExampleWeb.PageController/error" + ) - [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) + [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) - assert event[:status] == 500 - assert event[:"phoenix.endpoint"] == "PhxExampleWeb.Endpoint" - assert event[:"phoenix.router"] == "PhxExampleWeb.Router" - assert event[:"phoenix.controller"] == "PhxExampleWeb.PageController" - assert event[:"phoenix.action"] == "error" - assert event[:error] - end + assert event[:status] == 500 + assert event[:"phoenix.endpoint"] =~ "PhxExampleWeb" + assert event[:"phoenix.router"] == "PhxExampleWeb.Router" + assert event[:"phoenix.controller"] == "PhxExampleWeb.PageController" + assert event[:"phoenix.action"] == "error" + assert event[:error] + end - @tag :capture_log - test "Phoenix LiveView error" do - TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) + @tag :capture_log + test "Phoenix LiveView error" do + TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body, status_code: 500}} = request("/phx/live_error") + {:ok, %{body: body, status_code: 500}} = request("/phx/live_error", unquote(server)) - assert body =~ "Oops, Internal Server Error" + assert body =~ "Oops, Internal Server Error" - metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) + metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) - assert TestSupport.find_metric( - metrics, - "WebTransaction/Phoenix/PhxExampleWeb.ErrorLive/index" - ) + assert TestSupport.find_metric( + metrics, + "WebTransaction/Phoenix/PhxExampleWeb.ErrorLive/index" + ) - [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) + [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) - assert event[:status] == 500 - assert event[:"phoenix.endpoint"] == "PhxExampleWeb.Endpoint" - assert event[:"phoenix.router"] == "PhxExampleWeb.Router" - assert event[:"phoenix.controller"] == "Phoenix.LiveView.Plug" - assert event[:"phoenix.action"] == "index" - assert event[:error] - end + assert event[:status] == 500 + assert event[:"phoenix.endpoint"] =~ "PhxExampleWeb" + assert event[:"phoenix.router"] == "PhxExampleWeb.Router" + assert event[:"phoenix.controller"] == "Phoenix.LiveView.Plug" + assert event[:"phoenix.action"] == "index" + assert event[:error] + end + + test "Phoenix route not found" do + TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) + TestSupport.restart_harvest_cycle(Collector.ErrorTrace.HarvestCycle) - test "Phoenix route not found" do - TestSupport.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestSupport.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - TestSupport.restart_harvest_cycle(Collector.ErrorTrace.HarvestCycle) + {:ok, %{body: body, status_code: 404}} = request("/not_found", unquote(server)) + assert body =~ "Not Found" - {:ok, %{body: body, status_code: 404}} = request("/not_found") - assert body =~ "Not Found" + metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) - metrics = TestSupport.gather_harvest(Collector.Metric.Harvester) + metric = + case unquote(server) do + :cowboy -> "WebTransaction/Phoenix/PhxExampleWeb.Endpoint/GET" + :bandit -> "WebTransaction/Phoenix/PhxExampleWeb.BanditEndpoint/GET" + end - assert TestSupport.find_metric( - metrics, - "WebTransaction/Phoenix/PhxExampleWeb.Endpoint/GET" - ) + assert TestSupport.find_metric(metrics, metric) - [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) + [[_, event]] = TestSupport.gather_harvest(Collector.TransactionEvent.Harvester) - assert event[:status] == 404 - assert event[:"phoenix.endpoint"] == "PhxExampleWeb.Endpoint" - assert event[:"phoenix.router"] == "PhxExampleWeb.Router" - refute event[:"phoenix.controller"] - refute event[:error] + assert event[:status] == 404 + assert event[:"phoenix.endpoint"] =~ "PhxExampleWeb" + assert event[:"phoenix.router"] == "PhxExampleWeb.Router" + refute event[:"phoenix.controller"] + refute event[:error] - errors = TestSupport.gather_harvest(Collector.ErrorTrace.Harvester) - assert errors == [] + errors = TestSupport.gather_harvest(Collector.ErrorTrace.Harvester) + assert errors == [] + end + end end - defp request(path) do - config = Application.get_env(:phx_example, PhxExampleWeb.Endpoint) + defp request(path, server) do + config = + case server do + :cowboy -> Application.get_env(:phx_example, PhxExampleWeb.Endpoint) + :bandit -> Application.get_env(:phx_example, PhxExampleWeb.BanditEndpoint) + end + NewRelic.Util.HTTP.get("http://localhost:#{config[:http][:port]}#{path}") end end diff --git a/examples/apps/test_support/lib/test_support.ex b/examples/apps/test_support/lib/test_support.ex index c779179e..b4dea2be 100644 --- a/examples/apps/test_support/lib/test_support.ex +++ b/examples/apps/test_support/lib/test_support.ex @@ -6,7 +6,7 @@ defmodule TestSupport do def gather_harvest(harvester) do Process.sleep(300) - harvester.gather_harvest + harvester.gather_harvest() end def restart_harvest_cycle(harvest_cycle) do diff --git a/examples/mix.lock b/examples/mix.lock index bb88866c..aab6ad74 100644 --- a/examples/mix.lock +++ b/examples/mix.lock @@ -1,4 +1,5 @@ %{ + "bandit": {:hex, :bandit, "1.5.7", "6856b1e1df4f2b0cb3df1377eab7891bec2da6a7fd69dc78594ad3e152363a50", [:mix], [{:hpax, "~> 1.0.0", [hex: :hpax, repo: "hexpm", optional: false]}, {:plug, "~> 1.14", [hex: :plug, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}, {:thousand_island, "~> 1.0", [hex: :thousand_island, repo: "hexpm", optional: false]}, {:websock, "~> 0.5", [hex: :websock, repo: "hexpm", optional: false]}], "hexpm", "f2dd92ae87d2cbea2fa9aa1652db157b6cba6c405cb44d4f6dd87abba41371cd"}, "castore": {:hex, :castore, "0.1.9", "eb08a94c12ebff92a92d844c6ccd90728dc7662aab9bdc8b3b785ba653c499d5", [:mix], [], "hexpm", "99c3a38ad9c0bab03fee1418c98390da1a31f3b85e317db5840d51a1443d26c8"}, "cc_precompiler": {:hex, :cc_precompiler, "0.1.9", "e8d3364f310da6ce6463c3dd20cf90ae7bbecbf6c5203b98bf9b48035592649b", [:mix], [{:elixir_make, "~> 0.7", [hex: :elixir_make, repo: "hexpm", optional: false]}], "hexpm", "9dcab3d0f3038621f1601f13539e7a9ee99843862e66ad62827b0c42b2f58a54"}, "certifi": {:hex, :certifi, "2.5.3", "70bdd7e7188c804f3a30ee0e7c99655bc35d8ac41c23e12325f36ab449b70651", [:rebar3], [{:parse_trans, "~>3.3", [hex: :parse_trans, repo: "hexpm", optional: false]}], "hexpm", "ed516acb3929b101208a9d700062d520f3953da3b6b918d866106ffa980e1c10"}, @@ -13,6 +14,7 @@ "elixir_make": {:hex, :elixir_make, "0.7.7", "7128c60c2476019ed978210c245badf08b03dbec4f24d05790ef791da11aa17c", [:mix], [{:castore, "~> 0.1 or ~> 1.0", [hex: :castore, repo: "hexpm", optional: true]}], "hexpm", "5bc19fff950fad52bbe5f211b12db9ec82c6b34a9647da0c2224b8b8464c7e6c"}, "exqlite": {:hex, :exqlite, "0.17.0", "865ab503debde7913ffa02b58838ab92885165978f4c88d8169ee8688c655d1e", [:make, :mix], [{:cc_precompiler, "~> 0.1", [hex: :cc_precompiler, repo: "hexpm", optional: false]}, {:db_connection, "~> 2.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:elixir_make, "~> 0.7", [hex: :elixir_make, repo: "hexpm", optional: false]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "719fa7986fed242839629a907d60f774000c1d2dc03ba6ba05fcd30579f2ab45"}, "hackney": {:hex, :hackney, "1.17.0", "717ea195fd2f898d9fe9f1ce0afcc2621a41ecfe137fae57e7fe6e9484b9aa99", [:rebar3], [{:certifi, "~>2.5", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "~>6.1.0", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "~>1.0.0", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "~>1.1", [hex: :mimerl, repo: "hexpm", optional: false]}, {:parse_trans, "~>3.3", [hex: :parse_trans, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "~>1.1.0", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}, {:unicode_util_compat, "~>0.7.0", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm", "64c22225f1ea8855f584720c0e5b3cd14095703af1c9fbc845ba042811dc671c"}, + "hpax": {:hex, :hpax, "1.0.0", "28dcf54509fe2152a3d040e4e3df5b265dcb6cb532029ecbacf4ce52caea3fd2", [:mix], [], "hexpm", "7f1314731d711e2ca5fdc7fd361296593fc2542570b3105595bb0bc6d0fad601"}, "httpoison": {:hex, :httpoison, "1.8.0", "6b85dea15820b7804ef607ff78406ab449dd78bed923a49c7160e1886e987a3d", [:mix], [{:hackney, "~> 1.17", [hex: :hackney, repo: "hexpm", optional: false]}], "hexpm", "28089eaa98cf90c66265b6b5ad87c59a3729bea2e74e9d08f9b51eb9729b3c3a"}, "idna": {:hex, :idna, "6.1.1", "8a63070e9f7d0c62eb9d9fcb360a7de382448200fbbd1b106cc96d3d8099df8d", [:rebar3], [{:unicode_util_compat, "~>0.7.0", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm", "92376eb7894412ed19ac475e4a86f7b413c1b9fbb5bd16dccd57934157944cea"}, "jason": {:hex, :jason, "1.4.1", "af1504e35f629ddcdd6addb3513c3853991f694921b1b9368b0bd32beb9f1b63", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "fbb01ecdfd565b56261302f7e1fcc27c4fb8f32d56eab74db621fc154604a7a1"}, @@ -35,6 +37,7 @@ "redix": {:hex, :redix, "1.0.0", "4f310341744ffceab3031394450a4e603d4d1001a697c3f18ae57ae776cbd3fb", [:mix], [{:castore, "~> 0.1.0", [hex: :castore, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "8c8d9b33b5491737adcd5bb9e0f43b85212a384ac0042f64c156113518266ecb"}, "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.7", "354c321cf377240c7b8716899e182ce4890c5938111a1296add3ec74cf1715df", [:make, :mix, :rebar3], [], "hexpm", "fe4c190e8f37401d30167c8c405eda19469f34577987c76dde613e838bbc67f8"}, "telemetry": {:hex, :telemetry, "0.4.3", "a06428a514bdbc63293cd9a6263aad00ddeb66f608163bdec7c8995784080818", [:rebar3], [], "hexpm", "eb72b8365ffda5bed68a620d1da88525e326cb82a75ee61354fc24b844768041"}, + "thousand_island": {:hex, :thousand_island, "1.3.5", "6022b6338f1635b3d32406ff98d68b843ba73b3aa95cfc27154223244f3a6ca5", [:mix], [{:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "2be6954916fdfe4756af3239fb6b6d75d0b8063b5df03ba76fd8a4c87849e180"}, "unicode_util_compat": {:hex, :unicode_util_compat, "0.7.0", "bc84380c9ab48177092f43ac89e4dfa2c6d62b40b8bd132b1059ecc7232f9a78", [:rebar3], [], "hexpm", "25eee6d67df61960cf6a794239566599b09e17e668d3700247bc498638152521"}, "websock": {:hex, :websock, "0.5.3", "2f69a6ebe810328555b6fe5c831a851f485e303a7c8ce6c5f675abeb20ebdadc", [:mix], [], "hexpm", "6105453d7fac22c712ad66fab1d45abdf049868f253cf719b625151460b8b453"}, "websock_adapter": {:hex, :websock_adapter, "0.5.5", "9dfeee8269b27e958a65b3e235b7e447769f66b5b5925385f5a569269164a210", [:mix], [{:bandit, ">= 0.6.0", [hex: :bandit, repo: "hexpm", optional: true]}, {:plug, "~> 1.14", [hex: :plug, repo: "hexpm", optional: false]}, {:plug_cowboy, "~> 2.6", [hex: :plug_cowboy, repo: "hexpm", optional: true]}, {:websock, "~> 0.5", [hex: :websock, repo: "hexpm", optional: false]}], "hexpm", "4b977ba4a01918acbf77045ff88de7f6972c2a009213c515a445c48f224ffce9"}, diff --git a/lib/new_relic/sampler/beam.ex b/lib/new_relic/sampler/beam.ex index 0645e771..528124a2 100644 --- a/lib/new_relic/sampler/beam.ex +++ b/lib/new_relic/sampler/beam.ex @@ -104,6 +104,7 @@ defmodule NewRelic.Sampler.Beam do safe_div(active, total) end - defp safe_div(_, 0.0), do: 0.0 + defp safe_div(_, +0.0), do: 0.0 + defp safe_div(_, -0.0), do: 0.0 defp safe_div(a, b), do: a / b end diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex index 85d84f05..6ba708f8 100644 --- a/lib/new_relic/telemetry/plug.ex +++ b/lib/new_relic/telemetry/plug.ex @@ -96,15 +96,16 @@ defmodule NewRelic.Telemetry.Plug do meta, _config ) do - Transaction.Reporter.start_transaction(:web) + measurements = Map.put_new(measurements, :system_time, System.system_time()) - system_time = get_system_time(measurements) + Transaction.Reporter.start_transaction(:web) + headers = get_headers(meta, server) if NewRelic.Config.enabled?(), - do: DistributedTrace.start(:http, get_headers(meta, server)) + do: DistributedTrace.start(:http, headers) - add_start_attrs(meta, system_time, server) - maybe_report_queueing(meta, server) + add_start_attrs(meta, measurements, headers, server) + maybe_report_queueing(headers) end def handle_event( @@ -118,35 +119,35 @@ defmodule NewRelic.Telemetry.Plug do def handle_event( [server, :request, :stop], - %{duration: duration} = meas, + meas, meta, _config ) do - add_stop_attrs(meas, meta, duration, server) + add_stop_attrs(meas, meta, server) add_stop_error_attrs(meta) Transaction.Reporter.stop_transaction(:web) end - # Don't treat 404 as an exception + # Don't treat cowboy 404 as an exception def handle_event( - [server, :request, :exception], - %{duration: duration} = meas, + [:cowboy, :request, :exception], + meas, %{resp_status: "404" <> _} = meta, _config ) do - add_stop_attrs(meas, meta, duration, server) + add_stop_attrs(meas, meta, :cowboy) Transaction.Reporter.stop_transaction(:web) end def handle_event( [server, :request, :exception], - %{duration: duration} = meas, + meas, %{kind: kind} = meta, _config ) do - add_stop_attrs(meas, meta, duration, server) + add_stop_attrs(meas, meta, server) {reason, stack} = reason_and_stack(meta) Transaction.Reporter.fail(%{kind: kind, reason: reason, stack: stack}) @@ -157,27 +158,25 @@ defmodule NewRelic.Telemetry.Plug do :ignore end - defp add_start_attrs(meta, system_time, :cowboy) do + defp add_start_attrs(meta, meas, headers, :cowboy) do [ pid: inspect(self()), - system_time: system_time, + system_time: meas[:system_time], host: meta.req.host, path: meta.req.path, remote_ip: meta.req.peer |> elem(0) |> :inet_parse.ntoa() |> to_string(), - referer: meta.req.headers["referer"], - user_agent: meta.req.headers["user-agent"], - content_type: meta.req.headers["content-type"], + referer: headers["referer"], + user_agent: headers["user-agent"], + content_type: headers["content-type"], request_method: meta.req.method ] |> NewRelic.add_attributes() end - defp add_start_attrs(meta, system_time, :bandit) do - headers = Map.new(meta.conn.req_headers) - + defp add_start_attrs(meta, meas, headers, :bandit) do [ pid: inspect(self()), - system_time: system_time, + system_time: meas[:system_time], host: meta.conn.host, path: meta.conn.request_path, remote_ip: meta.conn.remote_ip |> :inet_parse.ntoa() |> to_string(), @@ -191,11 +190,11 @@ defmodule NewRelic.Telemetry.Plug do @kb 1024 - defp add_stop_attrs(meas, meta, duration, :cowboy) do + defp add_stop_attrs(meas, meta, :cowboy) do info = Process.info(self(), [:memory, :reductions]) [ - duration: duration, + duration: meas[:duration], status: status_code(meta), memory_kb: info[:memory] / @kb, reductions: info[:reductions], @@ -207,16 +206,20 @@ defmodule NewRelic.Telemetry.Plug do |> NewRelic.add_attributes() end - defp add_stop_attrs(meas, meta, duration, :bandit) do + defp add_stop_attrs(meas, meta, :bandit) do info = Process.info(self(), [:memory, :reductions]) + duration = meas[:duration] || System.monotonic_time() - meas[:monotonic_time] + + resp_duration_ms = + meas[:resp_start_time] && + (meas[:resp_start_time] |> to_ms) - (meas[:resp_end_time] |> to_ms) [ duration: duration, - status: status_code(meta), + status: status_code(meta) || 500, memory_kb: info[:memory] / @kb, reductions: info[:reductions], - "bandit.resp_duration_ms": - (meas[:resp_start_time] |> to_ms) - (meas[:resp_end_time] |> to_ms), + "bandit.resp_duration_ms": resp_duration_ms, "bandit.resp_body_bytes": meas[:resp_body_bytes] ] |> NewRelic.add_attributes() @@ -257,9 +260,7 @@ defmodule NewRelic.Telemetry.Plug do do: System.convert_time_unit(duration, :native, :microsecond) / 1000 @request_start_header "x-request-start" - defp maybe_report_queueing(meta, server) do - headers = get_headers(meta, server) - + defp maybe_report_queueing(headers) do with true <- NewRelic.Config.feature?(:request_queuing_metrics), request_start when is_binary(request_start) <- headers[@request_start_header], {:ok, request_start_s} <- Util.RequestStart.parse(request_start) do @@ -267,9 +268,6 @@ defmodule NewRelic.Telemetry.Plug do end end - defp get_system_time(%{system_time: system_time}), do: system_time - defp get_system_time(%{monotonic_time: monotonic_time}), do: monotonic_time - defp get_headers(meta, :bandit) do Map.new(meta.conn.req_headers) end