From 9fa167240d00da0c7990ae623737cbbf6736c8bc Mon Sep 17 00:00:00 2001 From: robuye Date: Mon, 18 Mar 2024 13:08:58 +0100 Subject: [PATCH] feat: add metadata to telemetry events Added telemetry support to webhook handler and changed metadata included in API requests. API requests metadata contains some low cardinality fields that can be useful when visualising these metrics in other tools. For example using 'stripe.request.stop' event we can infer metrics for RED method and have visibility into all Stripe API endpoints. 'url' passed in to 'do_perform_request_and_retry' contains query params which can contain sensitive data such as emails so it is URI-parsed and all params are dropped. Webhooks are often important part of integration with Stripe and having telemetry in place for that is good idea too imo. --- lib/stripe/api.ex | 14 ++++- lib/stripe/webhook_plug.ex | 56 ++++++++++-------- test/stripe/api_test.exs | 39 +++++++++++++ test/stripe/webhook_plug_test.exs | 97 ++++++++++++++++++++++++++++++- 4 files changed, 178 insertions(+), 28 deletions(-) diff --git a/lib/stripe/api.ex b/lib/stripe/api.ex index d642f0d9..b7a32378 100644 --- a/lib/stripe/api.ex +++ b/lib/stripe/api.ex @@ -377,13 +377,21 @@ defmodule Stripe.API do defp do_perform_request_and_retry(method, url, headers, body, opts, {:attempts, attempts}) do response = - :telemetry.span(~w[stripe request]a, %{url: url, method: method}, fn -> + :telemetry.span(~w[stripe request]a, %{}, fn -> + telemetry_meta = %{ + endpoint: URI.parse(url).path, + method: method, + attempt: attempts, + stripe_api_version: headers["Stripe-Version"], + status: nil + } + case http_module().request(method, url, Map.to_list(headers), body, opts) do {:ok, status, _, _} = resp -> - {resp, %{status: status}} + {resp, %{telemetry_meta | status: status}} error -> - {error, %{}} + {error, telemetry_meta} end end) diff --git a/lib/stripe/webhook_plug.ex b/lib/stripe/webhook_plug.ex index 8b80b808..f81e37db 100644 --- a/lib/stripe/webhook_plug.ex +++ b/lib/stripe/webhook_plug.ex @@ -159,30 +159,38 @@ if Code.ensure_loaded?(Plug) do end defp handle_event!(handler, %Stripe.Event{} = event) do - case handler.handle_event(event) do - {:ok, _} -> - :ok - - :ok -> - :ok - - {:error, reason} when is_binary(reason) -> - {:handle_error, reason} - - {:error, reason} when is_atom(reason) -> - {:handle_error, Atom.to_string(reason)} - - :error -> - {:handle_error, ""} - - resp -> - raise """ - #{inspect(handler)}.handle_event/1 returned an invalid response. Expected {:ok, term}, :ok, {:error, reason} or :error - Got: #{inspect(resp)} - - Event data: #{inspect(event)} - """ - end + :telemetry.span(~w[stripe webhook]a, %{}, fn -> + telemetry_meta = %{event: event.type, handler_status: nil} + + case handler.handle_event(event) do + {:ok, _} -> + :ok + + :ok -> + :ok + + {:error, reason} when is_binary(reason) -> + {:handle_error, reason} + + {:error, reason} when is_atom(reason) -> + {:handle_error, Atom.to_string(reason)} + + :error -> + {:handle_error, ""} + + resp -> + raise """ + #{inspect(handler)}.handle_event/1 returned an invalid response. Expected {:ok, term}, :ok, {:error, reason} or :error + Got: #{inspect(resp)} + + Event data: #{inspect(event)} + """ + end + |> then(fn + :ok -> {:ok, %{telemetry_meta | handler_status: :ok}} + result -> {result, %{telemetry_meta | handler_status: :error}} + end) + end) end defp parse_secret!({m, f, a}), do: apply(m, f, a) diff --git a/test/stripe/api_test.exs b/test/stripe/api_test.exs index 715ab6ae..1937bdd2 100644 --- a/test/stripe/api_test.exs +++ b/test/stripe/api_test.exs @@ -2,6 +2,10 @@ defmodule Stripe.APITest do import Mox use Stripe.StripeCase + def telemetry_handler_fn(name, measurements, metadata, _config) do + send(self(), {:telemetry_event, name, measurements, metadata}) + end + test "works with non existent responses without issue" do {:error, %Stripe.Error{extra: %{http_status: 404}}} = Stripe.API.request(%{}, :get, "/", %{}, []) @@ -87,6 +91,41 @@ defmodule Stripe.APITest do end end + describe "telemetry" do + test "requests emit :start, :stop telemetry events", %{test: test} do + :telemetry.attach_many( + "#{test}", + [[:stripe, :request, :start], [:stripe, :request, :stop]], + &__MODULE__.telemetry_handler_fn/4, + nil + ) + + %{query: ~s|email: "test@example.com"|} + |> Stripe.API.request(:get, "/v1/customers/search", %{}, []) + + assert_received({ + :telemetry_event, + [:stripe, :request, :start], + %{monotonic_time: _}, + %{telemetry_span_context: _} + }) + + assert_received({ + :telemetry_event, + [:stripe, :request, :stop], + %{monotonic_time: _, duration: _}, + %{ + telemetry_span_context: _, + endpoint: "/v1/customers/search", + attempt: 0, + method: :get, + status: 200, + stripe_api_version: _ + } + }) + end + end + @tag :skip test "gets default api version" do Stripe.API.request(%{}, :get, "products", %{}, []) diff --git a/test/stripe/webhook_plug_test.exs b/test/stripe/webhook_plug_test.exs index a1463e7d..c2ddb1ec 100644 --- a/test/stripe/webhook_plug_test.exs +++ b/test/stripe/webhook_plug_test.exs @@ -3,7 +3,7 @@ defmodule Stripe.WebhookPlugTest do use Plug.Test alias Stripe.WebhookPlug - @valid_payload ~S({"object": "event"}) + @valid_payload ~S({"object": "event", "type": "customer.updated"}) @secret "secret" @opts WebhookPlug.init( @@ -46,6 +46,10 @@ defmodule Stripe.WebhookPlugTest do def get_value(:secret), do: @secret + def telemetry_handler_fn(name, measurements, metadata, _config) do + send(self(), {:telemetry_event, name, measurements, metadata}) + end + defp generate_signature_header(payload) do timestamp = System.system_time(:second) @@ -185,5 +189,96 @@ defmodule Stripe.WebhookPlugTest do WebhookPlug.call(conn, opts) end end + + test "emits :start, :exception telemetry events on exception", %{conn: conn, test: test} do + :telemetry.attach_many( + "#{test}", + [[:stripe, :webhook, :start], [:stripe, :webhook, :exception]], + &__MODULE__.telemetry_handler_fn/4, + nil + ) + + opts = + WebhookPlug.init( + at: "/webhook/stripe", + handler: __MODULE__.BadHandler, + secret: @secret + ) + + assert_raise RuntimeError, fn -> + WebhookPlug.call(conn, opts) + end + + assert_received({ + :telemetry_event, + [:stripe, :webhook, :start], + %{monotonic_time: _}, + %{telemetry_span_context: _} + }) + + assert_received({ + :telemetry_event, + [:stripe, :webhook, :exception], + %{monotonic_time: _, duration: _}, + %{kind: _, reason: _, stacktrace: _, telemetry_span_context: _} + }) + end + + test "emits :start, :stop telemetry events on soft failure", %{conn: conn, test: test} do + :telemetry.attach_many( + "#{test}", + [[:stripe, :webhook, :start], [:stripe, :webhook, :stop]], + &__MODULE__.telemetry_handler_fn/4, + nil + ) + + opts = + WebhookPlug.init( + at: "/webhook/stripe", + handler: __MODULE__.ErrorTupleAtomHandler, + secret: @secret + ) + + WebhookPlug.call(conn, opts) + + assert_received({ + :telemetry_event, + [:stripe, :webhook, :start], + %{monotonic_time: _}, + %{telemetry_span_context: _} + }) + + assert_received({ + :telemetry_event, + [:stripe, :webhook, :stop], + %{monotonic_time: _, duration: _}, + %{handler_status: :error, telemetry_span_context: _} + }) + end + + test "emits :start, :stop telemetry events on success", %{conn: conn, test: test} do + :telemetry.attach_many( + "#{test}", + [[:stripe, :webhook, :start], [:stripe, :webhook, :stop]], + &__MODULE__.telemetry_handler_fn/4, + nil + ) + + WebhookPlug.call(conn, @opts) + + assert_received({ + :telemetry_event, + [:stripe, :webhook, :start], + %{monotonic_time: _}, + %{telemetry_span_context: _} + }) + + assert_received({ + :telemetry_event, + [:stripe, :webhook, :stop], + %{monotonic_time: _, duration: _}, + %{handler_status: :ok, event: "customer.updated", telemetry_span_context: _} + }) + end end end