From fd0675ecacc3d1b077071d7ce97e41297c8b7066 Mon Sep 17 00:00:00 2001 From: Vince Foley Date: Fri, 27 Dec 2024 15:29:25 -0800 Subject: [PATCH 1/2] Add finch instrumentation --- README.md | 11 +- lib/new_relic.ex | 5 +- lib/new_relic/config.ex | 6 + lib/new_relic/distributed_trace.ex | 4 +- lib/new_relic/init.ex | 5 + lib/new_relic/telemetry/finch.ex | 256 ++++++++++++++++++++++++++ lib/new_relic/telemetry/supervisor.ex | 3 +- lib/new_relic/tracer.ex | 70 ++++--- lib/new_relic/tracer/macro.ex | 9 +- mix.exs | 3 +- mix.lock | 3 + test/support/test_helper.ex | 7 + test/telemetry/finch_test.exs | 105 +++++++++++ 13 files changed, 435 insertions(+), 52 deletions(-) create mode 100644 lib/new_relic/telemetry/finch.ex create mode 100644 test/telemetry/finch_test.exs diff --git a/README.md b/README.md index 5351a6d4..02bba798 100644 --- a/README.md +++ b/README.md @@ -90,6 +90,7 @@ Some common Elixir packages are auto-instrumented via [`telemetry`](https://gith * [`Phoenix`](https://github.com/phoenixframework/phoenix): See [NewRelic.Telemetry.Phoenix](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Phoenix.html) for details. * [`Ecto`](https://github.com/elixir-ecto/ecto): See [NewRelic.Telemetry.Ecto](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Ecto.html) for details. * [`Redix`](https://github.com/whatyouhide/redix): See [NewRelic.Telemetry.Redix](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Redix.html) for details. +* [`Finch`](https://github.com/sneako/finch): See [NewRelic.Telemetry.Finch](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Finch.html) for details. ## Agent features @@ -118,13 +119,13 @@ spawn(fn -> end) ``` -If you are using a `Task` to spawn work, you can use the pre-instrumented `NewRelic.Instrumented.Task` convienince module to make this easier. Just `alias` it in your module and all your Tasks will be instrumented. You may also use the functions directly. +If you are using a `Task` to spawn work, you can use the pre-instrumented `NewRelic.Instrumented.Task` convenience module to make this easier. Just `alias` it in your module and all your Tasks will be instrumented. You may also use the functions directly. ```elixir alias NewRelic.Instrumented.Task Task.Supervisor.async_nolink(MyTaskSupervisor, fn -> - # This process wil be automatically connected to the Transaction... + # This process will be automatically connected to the current Transaction... end) ``` @@ -145,15 +146,11 @@ end #### Distributed Tracing -Requests to other services can be traced with the combination of an additional outgoing header and an `:external` tracer. +Requests to other services can be connected with an additional outgoing header. ```elixir defmodule MyExternalService do - use NewRelic.Tracer - - @trace {:request, category: :external} def request(method, url, headers) do - NewRelic.set_span(:http, url: url, method: method, component: "HttpClient") headers = headers ++ NewRelic.distributed_trace_headers(:http) HttpClient.request(method, url, headers) end diff --git a/lib/new_relic.ex b/lib/new_relic.ex index fb5858fa..b9f2b51a 100644 --- a/lib/new_relic.ex +++ b/lib/new_relic.ex @@ -163,7 +163,7 @@ defmodule NewRelic do @doc """ Advanced: - Call to manually disconnect the current proccess from the current Transaction. + Call to manually disconnect the current process from the current Transaction. """ defdelegate disconnect_from_transaction(), to: NewRelic.Transaction.Reporter @@ -174,7 +174,7 @@ defmodule NewRelic do - `:type` - `:generic` - Pass custom attributes - `:http` - Pass attributes `:url`, `:method`, `:component` - - `:datastore` - Pass attrributes `:statement`, `:instance`, `:address`, `:hostname`, + - `:datastore` - Pass attributes `:statement`, `:instance`, `:address`, `:hostname`, `:component` ## Examples @@ -205,6 +205,7 @@ defmodule NewRelic do * Call `distributed_trace_headers` immediately before making the request since calling the function marks the "start" time of the request. """ + @spec distributed_trace_headers(:http) :: [{key :: binary, value :: binary}] defdelegate distributed_trace_headers(type), to: NewRelic.DistributedTrace @doc """ diff --git a/lib/new_relic/config.ex b/lib/new_relic/config.ex index 4b24f60d..a16cfb2c 100644 --- a/lib/new_relic/config.ex +++ b/lib/new_relic/config.ex @@ -153,6 +153,8 @@ defmodule NewRelic.Config do * Controls all Redix instrumentation * `:oban_instrumentation_enabled` (default `true`) * Controls all Oban instrumentation + * `:finch_instrumentation_enabled` (default `true`) + * Controls all Finch instrumentation * `:request_queuing_metrics_enabled` * Controls collection of request queuing metrics @@ -197,6 +199,10 @@ defmodule NewRelic.Config do get(:features, :oban_instrumentation) end + def feature?(:finch_instrumentation) do + get(:features, :finch_instrumentation) + end + def feature?(:function_argument_collection) do get(:features, :function_argument_collection) end diff --git a/lib/new_relic/distributed_trace.ex b/lib/new_relic/distributed_trace.ex index 8a2cb0be..895f4c9a 100644 --- a/lib/new_relic/distributed_trace.ex +++ b/lib/new_relic/distributed_trace.ex @@ -244,8 +244,8 @@ defmodule NewRelic.DistributedTrace do def set_current_span(label: label, ref: ref) do current = {label, ref} - previous_span = Process.get(:nr_current_span) - previous_span_attrs = Process.get(:nr_current_span_attrs) + previous_span = Process.delete(:nr_current_span) + previous_span_attrs = Process.delete(:nr_current_span_attrs) Process.put(:nr_current_span, current) {current, previous_span, previous_span_attrs} end diff --git a/lib/new_relic/init.ex b/lib/new_relic/init.ex index c507ced5..7837bec2 100644 --- a/lib/new_relic/init.ex +++ b/lib/new_relic/init.ex @@ -103,6 +103,11 @@ defmodule NewRelic.Init do "NEW_RELIC_OBAN_INSTRUMENTATION_ENABLED", :oban_instrumentation_enabled ), + finch_instrumentation: + determine_feature( + "NEW_RELIC_FINCH_INSTRUMENTATION_ENABLED", + :finch_instrumentation_enabled + ), function_argument_collection: determine_feature( "NEW_RELIC_FUNCTION_ARGUMENT_COLLECTION_ENABLED", diff --git a/lib/new_relic/telemetry/finch.ex b/lib/new_relic/telemetry/finch.ex new file mode 100644 index 00000000..4638d0bb --- /dev/null +++ b/lib/new_relic/telemetry/finch.ex @@ -0,0 +1,256 @@ +defmodule NewRelic.Telemetry.Finch do + use GenServer + require Logger + + @moduledoc """ + Provides `Finch` instrumentation via `telemetry`. + + Finch requests are auto-discovered and instrumented as "external" calls. + + We automatically gather: + * Transaction segments + * External metrics + * External spans + + You can opt-out of this instrumentation via configuration. See `NewRelic.Config` for details. + """ + def start_link(_) do + config = %{ + enabled?: NewRelic.Config.feature?(:finch_instrumentation), + handler_id: {:new_relic, :finch} + } + + GenServer.start_link(__MODULE__, config, name: __MODULE__) + end + + @finch_request_start [:finch, :request, :start] + @finch_request_stop [:finch, :request, :stop] + @finch_request_exception [:finch, :request, :exception] + + @finch_events [ + @finch_request_start, + @finch_request_stop, + @finch_request_exception + ] + + @doc false + def init(%{enabled?: false}), do: :ignore + + def init(%{enabled?: true} = config) do + :telemetry.attach_many( + config.handler_id, + @finch_events, + &__MODULE__.handle_event/4, + config + ) + + Process.flag(:trap_exit, true) + {:ok, config} + end + + @doc false + def terminate(_reason, %{handler_id: handler_id}) do + :telemetry.detach(handler_id) + end + + def handle_event( + @finch_request_start, + %{monotonic_time: monotonic_time, system_time: system_time}, + %{request: request}, + config + ) do + if instrument?() do + {span, previous_span, previous_span_attrs} = + NewRelic.DistributedTrace.set_current_span( + label: {request.method, request.scheme, request.host, request.path}, + ref: make_ref() + ) + + Process.put( + config.handler_id, + %{ + start_time_mono: monotonic_time, + system_time: system_time, + span: span, + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + } + ) + end + end + + def handle_event( + @finch_request_stop, + %{monotonic_time: end_time_mono, duration: duration}, + %{name: finch_pool, request: request, result: result}, + config + ) do + if instrument?() do + %{ + start_time_mono: start_time_mono, + system_time: start_time, + span: span, + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + } = Process.delete(config.handler_id) + + metric_name = "External/#{request.host}/Finch/#{request.method}" + secondary_name = "#{request.host} - Finch/#{request.method}" + + duration_ms = System.convert_time_unit(duration, :native, :millisecond) + duration_s = duration_ms / 1000 + + id = span + parent_id = previous_span || :root + + url = + URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path}) + + result_attrs = + case result do + {:ok, %{__struct__: Finch.Response} = response} -> %{"response.status": response.status} + {:ok, _acc} -> %{} + {:error, exception} -> %{error: true, "error.message": Exception.message(exception)} + end + + NewRelic.Transaction.Reporter.add_trace_segment(%{ + primary_name: metric_name, + secondary_name: secondary_name, + attributes: %{}, + pid: self(), + id: span, + parent_id: parent_id, + start_time: start_time, + start_time_mono: start_time_mono, + end_time_mono: end_time_mono + }) + + NewRelic.report_span( + timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond), + duration_s: duration_s, + name: metric_name, + edge: [span: id, parent: parent_id], + category: "http", + attributes: + %{ + "request.url": url, + "request.method": request.method, + "request.client": "Finch", + "finch.pool": finch_pool + } + |> Map.merge(result_attrs) + ) + + NewRelic.incr_attributes( + "external.#{request.host}.call_count": 1, + "external.#{request.host}.duration_ms": duration_ms + ) + + NewRelic.report_metric( + {:external, url, "Finch", request.method}, + duration_s: duration_s + ) + + NewRelic.Transaction.Reporter.track_metric({ + {:external, url, "Finch", request.method}, + duration_s: duration_s + }) + + NewRelic.DistributedTrace.reset_span( + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + ) + end + end + + def handle_event( + @finch_request_exception, + %{duration: duration}, + %{kind: kind, reason: reason, name: finch_pool, request: request}, + config + ) do + if instrument?() do + %{ + system_time: start_time, + span: span, + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + } = Process.delete(config.handler_id) + + metric_name = "External/#{request.host}/Finch/#{request.method}" + + duration_ms = System.convert_time_unit(duration, :native, :millisecond) + duration_s = duration_ms / 1000 + + id = span + parent_id = previous_span || :root + + url = + URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path}) + + error_message = NewRelic.Util.Error.format_reason(kind, reason) + + NewRelic.report_span( + timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond), + duration_s: duration_s, + name: metric_name, + edge: [span: id, parent: parent_id], + category: "http", + attributes: %{ + error: true, + "error.message": error_message, + "request.url": url, + "request.method": request.method, + "request.client": "Finch", + "finch.pool": finch_pool + } + ) + + NewRelic.DistributedTrace.reset_span( + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + ) + end + end + + def handle_event(_event, _measurements, _meta, config) do + with %{ + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + } <- Process.delete(config.handler_id) do + NewRelic.DistributedTrace.reset_span( + previous_span: previous_span, + previous_span_attrs: previous_span_attrs + ) + end + end + + # Avoid double instrumenting in situation where + # application has manually instrumented externals already + defp instrument?() do + case Process.get(:nr_already_tracing_external) do + true -> + warn_once( + "[New Relic] Trace `:external` deprecated in favor of automatic Finch instrumentation. " <> + "Please remove @trace `category: :external` annotations from Finch requests, or disable " <> + "automatic Finch instrumentation." + ) + + false + + _ -> + true + end + end + + defp warn_once(message) do + case :persistent_term.get(__MODULE__, :not_logged) do + :logged -> + :skip + + :not_logged -> + :persistent_term.put(__MODULE__, :logged) + Logger.warning(message) + end + end +end diff --git a/lib/new_relic/telemetry/supervisor.ex b/lib/new_relic/telemetry/supervisor.ex index c8961035..92c8185d 100644 --- a/lib/new_relic/telemetry/supervisor.ex +++ b/lib/new_relic/telemetry/supervisor.ex @@ -13,7 +13,8 @@ defmodule NewRelic.Telemetry.Supervisor do NewRelic.Telemetry.Redix, NewRelic.Telemetry.Plug, NewRelic.Telemetry.Phoenix, - NewRelic.Telemetry.Oban + NewRelic.Telemetry.Oban, + NewRelic.Telemetry.Finch ] Supervisor.init(children, strategy: :one_for_one) diff --git a/lib/new_relic/tracer.ex b/lib/new_relic/tracer.ex index 7a015030..e99b51a5 100644 --- a/lib/new_relic/tracer.ex +++ b/lib/new_relic/tracer.ex @@ -16,55 +16,24 @@ defmodule NewRelic.Tracer do #### Example - Trace as a function: + Trace a function: ```elixir defmodule MyModule do use NewRelic.Tracer - @trace :func - def func do - # Will report as `MyModule.func/0` + @trace :my_function + def my_function do + # Will report as `MyModule.my_function/0` end - end - ``` - - #### Categories - - To categorize External Service calls you must give the trace annotation a category. - - You may also call `NewRelic.set_span/2` to provide better naming for metrics & spans, and additonally annotate the outgoing HTTP headers with the Distributed Tracing context to track calls across services. - ```elixir - defmodule MyExternalService do - use NewRelic.Tracer - - @trace {:request, category: :external} - def request(method, url, headers) do - NewRelic.set_span(:http, url: url, method: method, component: "HttpClient") - headers ++ NewRelic.distributed_trace_headers(:http) - HttpClient.request(method, url, headers) + @trace :alias + def my_function do + # Will report as `MyModule.my_function:alias/0` end end ``` - This will: - * Post `External` metrics to APM - * Add custom attributes to Transaction events: - - `external_call_count` - - `external_duration_ms` - - `external.MyExternalService.query.call_count` - - `external.MyExternalService.query.duration_ms` - - Transactions that call the traced `ExternalService` functions will contain `external_call_count` attribute - - ```elixir - get "/endpoint" do - ExternalService.request(:get, url, headers) - send_resp(conn, 200, "ok") - end - ``` - #### Arguments By default, arguments are inspected and recorded along with traces. You can opt-out of function argument tracing on individual tracers: @@ -83,6 +52,31 @@ defmodule NewRelic.Tracer do This will prevent the argument values from becoming part of Transaction Traces. This may also be configured globally via `Application` config. See `NewRelic.Config` for details. + + #### External Service calls + + > #### Finch {: .warning} + > + > `Finch` requests are auto-instrumented, so you don't need to use `category: :external` tracers or call `set_span` if you use `Finch`. + > You may still want to use a normal tracer for functions that make HTTP requests if they do additional work worth instrumenting. + > Automatic `Finch` instrumentation can not inject Distributed Trace headers, so that must still be done manually. + + To manually instrument External Service calls you must give the trace annotation a category. + + You may also call `NewRelic.set_span/2` to provide better naming for metrics & spans, and additionally annotate the outgoing HTTP headers with the Distributed Tracing context to track calls across services. + + ```elixir + defmodule MyExternalService do + use NewRelic.Tracer + + @trace {:request, category: :external} + def request(method, url, headers) do + NewRelic.set_span(:http, url: url, method: method, component: "HttpClient") + headers ++ NewRelic.distributed_trace_headers(:http) + HttpClient.request(method, url, headers) + end + end + ``` """ defmacro __using__(_args) do diff --git a/lib/new_relic/tracer/macro.ex b/lib/new_relic/tracer/macro.ex index a071c890..a8ce2333 100644 --- a/lib/new_relic/tracer/macro.ex +++ b/lib/new_relic/tracer/macro.ex @@ -82,7 +82,7 @@ defmodule NewRelic.Tracer.Macro do def trace_deprecated?({_, category: :datastore}, module, name) do Logger.warning( - "[New Relic] Trace `:datastore` deprecated in favor of automatic ecto instrumentation. " <> + "[New Relic] Trace `:datastore` deprecated in favor of automatic Ecto instrumentation. " <> "Please remove @trace from #{inspect(module)}.#{name}" ) @@ -177,6 +177,11 @@ defmodule NewRelic.Tracer.Macro do def traced_function_body(body, module, function, args, trace_info) do quote do + with {_, opts} <- unquote(trace_info), + :external <- Keyword.get(opts, :category) do + Process.put(:nr_already_tracing_external, true) + end + current_ref = make_ref() {span, previous_span, previous_span_attrs} = @@ -236,6 +241,8 @@ defmodule NewRelic.Tracer.Macro do previous_span: previous_span, previous_span_attrs: previous_span_attrs ) + + Process.delete(:nr_already_tracing_external) end end end diff --git a/mix.exs b/mix.exs index f55ac098..7ed655e5 100644 --- a/mix.exs +++ b/mix.exs @@ -53,7 +53,8 @@ defmodule NewRelic.Mixfile do {:ecto_sql, ">= 3.4.0", optional: true}, {:ecto, ">= 3.9.5", optional: true}, {:redix, ">= 0.11.0", optional: true}, - {:oban, ">= 2.0.0", optional: true} + {:oban, ">= 2.0.0", optional: true}, + {:finch, ">= 0.18.0", optional: true} ] end diff --git a/mix.lock b/mix.lock index f3b2a2ec..4eed00ac 100644 --- a/mix.lock +++ b/mix.lock @@ -10,15 +10,18 @@ "ecto": {:hex, :ecto, "3.11.1", "4b4972b717e7ca83d30121b12998f5fcdc62ba0ed4f20fd390f16f3270d85c3e", [:mix], [{:decimal, "~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "ebd3d3772cd0dfcd8d772659e41ed527c28b2a8bde4b00fe03e0463da0f1983b"}, "ecto_sql": {:hex, :ecto_sql, "3.11.1", "e9abf28ae27ef3916b43545f9578b4750956ccea444853606472089e7d169470", [:mix], [{:db_connection, "~> 2.4.1 or ~> 2.5", [hex: :db_connection, repo: "hexpm", optional: false]}, {:ecto, "~> 3.11.0", [hex: :ecto, repo: "hexpm", optional: false]}, {:myxql, "~> 0.6.0", [hex: :myxql, repo: "hexpm", optional: true]}, {:postgrex, "~> 0.16.0 or ~> 0.17.0 or ~> 1.0", [hex: :postgrex, repo: "hexpm", optional: true]}, {:tds, "~> 2.1.1 or ~> 2.2", [hex: :tds, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4.0 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "ce14063ab3514424276e7e360108ad6c2308f6d88164a076aac8a387e1fea634"}, "ex_doc": {:hex, :ex_doc, "0.35.1", "de804c590d3df2d9d5b8aec77d758b00c814b356119b3d4455e4b8a8687aecaf", [:mix], [{:earmark_parser, "~> 1.4.39", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_c, ">= 0.1.0", [hex: :makeup_c, repo: "hexpm", optional: true]}, {:makeup_elixir, "~> 0.14 or ~> 1.0", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1 or ~> 1.0", [hex: :makeup_erlang, repo: "hexpm", optional: false]}, {:makeup_html, ">= 0.1.0", [hex: :makeup_html, repo: "hexpm", optional: true]}], "hexpm", "2121c6402c8d44b05622677b761371a759143b958c6c19f6558ff64d0aed40df"}, + "finch": {:hex, :finch, "0.19.0", "c644641491ea854fc5c1bbaef36bfc764e3f08e7185e1f084e35e0672241b76d", [:mix], [{:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:mint, "~> 1.6.2 or ~> 1.7", [hex: :mint, repo: "hexpm", optional: false]}, {:nimble_options, "~> 0.4 or ~> 1.0", [hex: :nimble_options, repo: "hexpm", optional: false]}, {:nimble_pool, "~> 1.1", [hex: :nimble_pool, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "fc5324ce209125d1e2fa0fcd2634601c52a787aff1cd33ee833664a5af4ea2b6"}, "hpax": {:hex, :hpax, "1.0.2", "762df951b0c399ff67cc57c3995ec3cf46d696e41f0bba17da0518d94acd4aac", [:mix], [], "hexpm", "2f09b4c1074e0abd846747329eaa26d535be0eb3d189fa69d812bfb8bfefd32f"}, "jason": {:hex, :jason, "1.4.1", "af1504e35f629ddcdd6addb3513c3853991f694921b1b9368b0bd32beb9f1b63", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "fbb01ecdfd565b56261302f7e1fcc27c4fb8f32d56eab74db621fc154604a7a1"}, "makeup": {:hex, :makeup, "1.2.1", "e90ac1c65589ef354378def3ba19d401e739ee7ee06fb47f94c687016e3713d1", [:mix], [{:nimble_parsec, "~> 1.4", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "d36484867b0bae0fea568d10131197a4c2e47056a6fbe84922bf6ba71c8d17ce"}, "makeup_elixir": {:hex, :makeup_elixir, "1.0.1", "e928a4f984e795e41e3abd27bfc09f51db16ab8ba1aebdba2b3a575437efafc2", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "7284900d412a3e5cfd97fdaed4f5ed389b8f2b4cb49efc0eb3bd10e2febf9507"}, "makeup_erlang": {:hex, :makeup_erlang, "1.0.1", "c7f58c120b2b5aa5fd80d540a89fdf866ed42f1f3994e4fe189abebeab610839", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "8a89a1eeccc2d798d6ea15496a6e4870b75e014d1af514b1b71fa33134f57814"}, "mime": {:hex, :mime, "2.0.5", "dc34c8efd439abe6ae0343edbb8556f4d63f178594894720607772a041b04b02", [:mix], [], "hexpm", "da0d64a365c45bc9935cc5c8a7fc5e49a0e0f9932a761c55d6c52b142780a05c"}, + "mint": {:hex, :mint, "1.6.2", "af6d97a4051eee4f05b5500671d47c3a67dac7386045d87a904126fd4bbcea2e", [:mix], [{:castore, "~> 0.1.0 or ~> 1.0", [hex: :castore, repo: "hexpm", optional: true]}, {:hpax, "~> 0.1.1 or ~> 0.2.0 or ~> 1.0", [hex: :hpax, repo: "hexpm", optional: false]}], "hexpm", "5ee441dffc1892f1ae59127f74afe8fd82fda6587794278d924e4d90ea3d63f9"}, "nimble_options": {:hex, :nimble_options, "1.1.0", "3b31a57ede9cb1502071fade751ab0c7b8dbe75a9a4c2b5bbb0943a690b63172", [:mix], [], "hexpm", "8bbbb3941af3ca9acc7835f5655ea062111c9c27bcac53e004460dfd19008a99"}, "nimble_parsec": {:hex, :nimble_parsec, "1.4.0", "51f9b613ea62cfa97b25ccc2c1b4216e81df970acd8e16e8d1bdc58fef21370d", [:mix], [], "hexpm", "9c565862810fb383e9838c1dd2d7d2c437b3d13b267414ba6af33e50d2d1cf28"}, "oban": {:hex, :oban, "2.18.3", "1608c04f8856c108555c379f2f56bc0759149d35fa9d3b825cb8a6769f8ae926", [:mix], [{:ecto_sql, "~> 3.10", [hex: :ecto_sql, repo: "hexpm", optional: false]}, {:ecto_sqlite3, "~> 0.9", [hex: :ecto_sqlite3, repo: "hexpm", optional: true]}, {:jason, "~> 1.1", [hex: :jason, repo: "hexpm", optional: false]}, {:postgrex, "~> 0.16", [hex: :postgrex, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "36ca6ca84ef6518f9c2c759ea88efd438a3c81d667ba23b02b062a0aa785475e"}, + "nimble_pool": {:hex, :nimble_pool, "1.1.0", "bf9c29fbdcba3564a8b800d1eeb5a3c58f36e1e11d7b7fb2e084a643f645f06b", [:mix], [], "hexpm", "af2e4e6b34197db81f7aad230c1118eac993acc0dae6bc83bac0126d4ae0813a"}, "phoenix": {:hex, :phoenix, "1.7.9", "9a2b873e2cb3955efdd18ad050f1818af097fa3f5fc3a6aaba666da36bdd3f02", [:mix], [{:castore, ">= 0.0.0", [hex: :castore, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:phoenix_pubsub, "~> 2.1", [hex: :phoenix_pubsub, repo: "hexpm", optional: false]}, {:phoenix_template, "~> 1.0", [hex: :phoenix_template, repo: "hexpm", optional: false]}, {:phoenix_view, "~> 2.0", [hex: :phoenix_view, repo: "hexpm", optional: true]}, {:plug, "~> 1.14", [hex: :plug, repo: "hexpm", optional: false]}, {:plug_cowboy, "~> 2.6", [hex: :plug_cowboy, repo: "hexpm", optional: true]}, {:plug_crypto, "~> 1.2 or ~> 2.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}, {:websock_adapter, "~> 0.5.3", [hex: :websock_adapter, repo: "hexpm", optional: false]}], "hexpm", "83e32da028272b4bfd076c61a964e6d2b9d988378df2f1276a0ed21b13b5e997"}, "phoenix_pubsub": {:hex, :phoenix_pubsub, "2.1.3", "3168d78ba41835aecad272d5e8cd51aa87a7ac9eb836eabc42f6e57538e3731d", [:mix], [], "hexpm", "bba06bc1dcfd8cb086759f0edc94a8ba2bc8896d5331a1e2c2902bf8e36ee502"}, "phoenix_template": {:hex, :phoenix_template, "1.0.4", "e2092c132f3b5e5b2d49c96695342eb36d0ed514c5b252a77048d5969330d639", [:mix], [{:phoenix_html, "~> 2.14.2 or ~> 3.0 or ~> 4.0", [hex: :phoenix_html, repo: "hexpm", optional: true]}], "hexpm", "2c0c81f0e5c6753faf5cca2f229c9709919aba34fab866d3bc05060c9c444206"}, diff --git a/test/support/test_helper.ex b/test/support/test_helper.ex index b654116f..4fb1fb89 100644 --- a/test/support/test_helper.ex +++ b/test/support/test_helper.ex @@ -59,6 +59,13 @@ defmodule TestHelper do end) end + def find_span(spans, name) do + Enum.find_value(spans, fn + [%{name: ^name} = span, _, _] -> span + _span -> false + end) + end + def simulate_agent_enabled(_context) do Process.whereis(Harvest.TaskSupervisor) || NewRelic.EnabledSupervisor.start_link(:ok) diff --git a/test/telemetry/finch_test.exs b/test/telemetry/finch_test.exs new file mode 100644 index 00000000..95cb9ed0 --- /dev/null +++ b/test/telemetry/finch_test.exs @@ -0,0 +1,105 @@ +defmodule NewRelic.Telemetry.FinchTest do + use ExUnit.Case + alias NewRelic.Harvest.Collector + + setup do + TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestHelper.restart_harvest_cycle(Collector.SpanEvent.HarvestCycle) + send(NewRelic.DistributedTrace.BackoffSampler, :reset) + + start_supervised({Finch, name: __MODULE__}) + + on_exit(fn -> + TestHelper.pause_harvest_cycle(Collector.Metric.HarvestCycle) + TestHelper.pause_harvest_cycle(Collector.SpanEvent.HarvestCycle) + end) + end + + test "finch external metrics" do + request("https://httpstat.us/200") + + metrics = TestHelper.gather_harvest(Collector.Metric.Harvester) + + assert TestHelper.find_metric(metrics, "External/httpstat.us/Finch/GET", 1) + assert TestHelper.find_metric(metrics, "External/httpstat.us/all", 1) + assert TestHelper.find_metric(metrics, "External/all", 1) + end + + test "[:finch, :request, :stop] - 200" do + Task.async(fn -> + NewRelic.start_transaction("FinchTest", "200") + request("https://httpstat.us/200") + end) + |> Task.await() + + span_events = TestHelper.gather_harvest(Collector.SpanEvent.Harvester) + + external_span = TestHelper.find_span(span_events, "External/httpstat.us/Finch/GET") + + assert external_span[:"request.url"] == "https://httpstat.us/200" + assert external_span[:"response.status"] == 200 + end + + test "[:finch, :request, :stop] - 500" do + Task.async(fn -> + NewRelic.start_transaction("FinchTest", "500") + request("https://httpstat.us/500") + end) + |> Task.await() + + span_events = TestHelper.gather_harvest(Collector.SpanEvent.Harvester) + + external_span = TestHelper.find_span(span_events, "External/httpstat.us/Finch/GET") + + assert external_span[:"request.url"] == "https://httpstat.us/500" + assert external_span[:"response.status"] == 500 + end + + test "[:finch, :request, :stop] - :error" do + Task.async(fn -> + NewRelic.start_transaction("FinchTest", "Error") + request("https://nxdomain") + end) + |> Task.await() + + span_events = TestHelper.gather_harvest(Collector.SpanEvent.Harvester) + + external_span = TestHelper.find_span(span_events, "External/nxdomain/Finch/GET") + + assert external_span[:"request.url"] == "https://nxdomain/" + assert external_span[:error] == true + assert external_span[:"error.message"] |> is_binary() + end + + @tag :capture_log + test "[:finch, :request, :exception]" do + {:ok, pid} = + Task.start(fn -> + NewRelic.start_transaction("FinchTest", "Exception") + request("https://httpstat.us/200", :exception) + end) + + Process.monitor(pid) + assert_receive {:DOWN, _ref, :process, ^pid, _reason}, 1_000 + + span_events = TestHelper.gather_harvest(Collector.SpanEvent.Harvester) + + external_span = TestHelper.find_span(span_events, "External/httpstat.us/Finch/GET") + + assert external_span[:"request.url"] == "https://httpstat.us/200" + assert external_span[:error] == true + assert external_span[:"error.message"] =~ "Oops" + end + + defp request(url) do + Finch.build(:get, url) + |> Finch.request(__MODULE__) + end + + defp request(url, :exception) do + Finch.build(:get, url) + |> Finch.stream(__MODULE__, nil, fn _, _ -> + raise "Oops" + end) + end +end From 7b60d4ab45518100011ca971065ac5a9dd2225a4 Mon Sep 17 00:00:00 2001 From: Vince Foley Date: Thu, 2 Jan 2025 17:44:18 -0800 Subject: [PATCH 2/2] Fix dializyer complaint about trace_info --- lib/new_relic/tracer/macro.ex | 10 ++++++++-- lib/new_relic/tracer/report.ex | 7 +------ 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/lib/new_relic/tracer/macro.ex b/lib/new_relic/tracer/macro.ex index a8ce2333..191941db 100644 --- a/lib/new_relic/tracer/macro.ex +++ b/lib/new_relic/tracer/macro.ex @@ -176,8 +176,14 @@ defmodule NewRelic.Tracer.Macro do end def traced_function_body(body, module, function, args, trace_info) do + trace_annotation = + case trace_info do + {name, options} -> {name, options} + name -> {name, []} + end + quote do - with {_, opts} <- unquote(trace_info), + with {_, opts} <- unquote(trace_annotation), :external <- Keyword.get(opts, :category) do Process.put(:nr_already_tracing_external, true) end @@ -231,7 +237,7 @@ defmodule NewRelic.Tracer.Macro do Tracer.Report.call( {unquote(module), unquote(function), unquote(build_call_args(args))}, - unquote(trace_info), + unquote(trace_annotation), inspect(self()), {span, previous_span || :root}, {start_time, start_time_mono, end_time_mono, child_duration_ms, reductions} diff --git a/lib/new_relic/tracer/report.ex b/lib/new_relic/tracer/report.ex index 0d6107c4..3d099a47 100644 --- a/lib/new_relic/tracer/report.ex +++ b/lib/new_relic/tracer/report.ex @@ -16,12 +16,7 @@ defmodule NewRelic.Tracer.Report do edge, timing ) do - {name, options} = - case trace_annotation do - {name, options} -> {name, options} - name -> {name, []} - end - + {name, options} = trace_annotation category = Keyword.get(options, :category, :function) report(