From 4e0bcee9c8b6036d30573cf719f328eac9516317 Mon Sep 17 00:00:00 2001 From: robuye Date: Mon, 18 Mar 2024 13:08:58 +0100 Subject: [PATCH 1/6] 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..86455b94 100644 --- a/lib/stripe/api.ex +++ b/lib/stripe/api.ex @@ -376,14 +376,22 @@ defmodule Stripe.API do end defp do_perform_request_and_retry(method, url, headers, body, opts, {:attempts, attempts}) do + telemetry_meta = %{ + endpoint: URI.parse(url).path, + method: method, + attempt: attempts, + stripe_api_version: headers["Stripe-Version"], + status: nil + } + response = - :telemetry.span(~w[stripe request]a, %{url: url, method: method}, fn -> + :telemetry.span(~w[stripe request]a, telemetry_meta, fn -> 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..9661d228 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_meta = %{event: event.type, handler_status: nil} + + :telemetry.span(~w[stripe webhook]a, telemetry_meta, fn -> + 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..7d671075 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: _, event: "customer.updated"} + }) + 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 From 90eca297b7617b12c2748780e2393a80fa23d8ed Mon Sep 17 00:00:00 2001 From: robuye Date: Mon, 18 Mar 2024 16:58:05 +0100 Subject: [PATCH 2/6] chore: configure SHELL env in CI jobs Maybe fix problem with erlexec failing to start: ``` SHELL environment variable not set! [c_src/exec.cpp:609] Notice: 15:48:19.772 [notice] Application erlexec exited: :exec_app.start(:normal, []) returned an error: shutdown: failed to start child: :exec ** (EXIT) {:port_exited_with_status, 4} ``` --- .github/workflows/ci.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d82c8941..9d0a4eba 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -18,6 +18,7 @@ jobs: STRIPE_MOCK_VERSION: 0.144.0 STRIPE_SECRET_KEY: non_empty_string SKIP_STRIPE_MOCK_RUN: true + SHELL: bash runs-on: ubuntu-20.04 name: Test (OTP ${{matrix.otp}} / Elixir ${{matrix.elixir}}) strategy: From eb139da1b9062ae81fdf9688d0e773118e00c9eb Mon Sep 17 00:00:00 2001 From: robuye Date: Mon, 18 Mar 2024 17:05:41 +0100 Subject: [PATCH 3/6] chore: cleanup CI output Run mix compile before tests so the output is separate. Trace will make it easier to understand if some tests were excluded and such. --- .github/workflows/ci.yml | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 9d0a4eba..d649af63 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -39,10 +39,9 @@ jobs: with: otp-version: ${{ matrix.otp }} elixir-version: ${{ matrix.elixir }} - - name: Mix Dependencies - run: mix deps.get - - name: Test - run: mix test + - run: mix deps.get + - run: mix compile + - run: mix test --trace lint: runs-on: ubuntu-20.04 From 7fd5517103794412dffcdd03003a6bd58cbff31e Mon Sep 17 00:00:00 2001 From: robuye Date: Mon, 18 Mar 2024 17:43:32 +0100 Subject: [PATCH 4/6] chore: fix flaky tests Some tests are failing because query params are in wrong order. My fix is to ignore order and just checking all were set with correct value. --- test/support/stripe_case.ex | 25 +++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/test/support/stripe_case.ex b/test/support/stripe_case.ex index 14d70c92..89c707a0 100644 --- a/test/support/stripe_case.ex +++ b/test/support/stripe_case.ex @@ -6,14 +6,27 @@ defmodule Stripe.StripeCase do use ExUnit.CaseTemplate def assert_stripe_requested(expected_method, path, extra \\ []) do - expected_url = build_url(path, Keyword.get(extra, :query)) + expected_params = Keyword.get(extra, :query, %{}) + expected_path = URI.parse(path).path expected_body = Keyword.get(extra, :body) expected_headers = Keyword.get(extra, :headers) assert_received({method, url, headers, body, _}) + actual_uri = URI.parse(url) + + actual_query_params = + to_string(actual_uri.query) + |> URI.query_decoder() + |> Enum.into(%{}) + + Enum.each(expected_params, fn {key, value} -> + actual_val = Map.get(actual_query_params, to_string(key)) + assert actual_val == to_string(value) + end) + assert expected_method == method - assert expected_url == url + assert expected_path == actual_uri.path assert_stripe_request_body(expected_body, body) assert_stripe_request_headers(expected_headers, headers) @@ -51,14 +64,6 @@ defmodule Stripe.StripeCase do assert body == Stripe.URI.encode_query(expected_body) end - defp build_url(path, nil) do - stripe_base_url() <> path - end - - defp build_url(path, query_params) do - stripe_base_url() <> path <> "?" <> URI.encode_query(query_params) - end - defmodule HackneyMock do @doc """ Send message to the owning process for each request so we can assert that From 02cc4cf096036f9350eac7b21422101ba4c38001 Mon Sep 17 00:00:00 2001 From: robuye Date: Mon, 18 Mar 2024 17:53:36 +0100 Subject: [PATCH 5/6] chore: run mix format and add it to CI --- .github/workflows/ci.yml | 1 + test/stripe/util_test.exs | 9 +++++++-- test/support/stripe_mock_test.exs | 2 +- 3 files changed, 9 insertions(+), 3 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d649af63..60f976ee 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -76,3 +76,4 @@ jobs: - run: mix compile --warnings-as-errors - run: mix dialyzer --halt-exit-status - run: mix deps.unlock --check-unused + - run: mix format --check-formatted diff --git a/test/stripe/util_test.exs b/test/stripe/util_test.exs index 80504f9d..b2ac3c05 100644 --- a/test/stripe/util_test.exs +++ b/test/stripe/util_test.exs @@ -37,8 +37,13 @@ defmodule Stripe.UtilTest do assert object_name_to_module("billing_portal.session") == Stripe.BillingPortal.Session assert object_name_to_module("checkout.session") == Stripe.Checkout.Session - assert object_name_to_module("identity.verification_report") == Stripe.Identity.VerificationReport - assert object_name_to_module("identity.verification_session") == Stripe.Identity.VerificationSession + + assert object_name_to_module("identity.verification_report") == + Stripe.Identity.VerificationReport + + assert object_name_to_module("identity.verification_session") == + Stripe.Identity.VerificationSession + assert object_name_to_module("issuing.authorization") == Stripe.Issuing.Authorization assert object_name_to_module("issuing.card") == Stripe.Issuing.Card assert object_name_to_module("issuing.cardholder") == Stripe.Issuing.Cardholder diff --git a/test/support/stripe_mock_test.exs b/test/support/stripe_mock_test.exs index 0ead7b17..ee0f848b 100644 --- a/test/support/stripe_mock_test.exs +++ b/test/support/stripe_mock_test.exs @@ -10,7 +10,7 @@ defmodule Stripe.StripeMockTest do defp assert_port_open(port) do delay() - assert {:ok, socket} = :gen_tcp.connect('localhost', port, []) + assert {:ok, socket} = :gen_tcp.connect(~c"localhost", port, []) :gen_tcp.close(socket) end From 04b8c095a02889f4bae1c9ab7cb8334b9fdae6dc Mon Sep 17 00:00:00 2001 From: robuye Date: Tue, 19 Mar 2024 23:11:30 +0100 Subject: [PATCH 6/6] fixup: update telemetry metadata Updated naming and changed where metadata is constructed in order to keep original function short and focused. URL is stripped of query params to avoid leaking of sensitive data such as emails to logging systems. --- lib/stripe/api.ex | 36 ++++++++++++++++++++++++++++-------- test/stripe/api_test.exs | 16 ++++++++++------ 2 files changed, 38 insertions(+), 14 deletions(-) diff --git a/lib/stripe/api.ex b/lib/stripe/api.ex index 86455b94..86640ca4 100644 --- a/lib/stripe/api.ex +++ b/lib/stripe/api.ex @@ -217,6 +217,22 @@ defmodule Stripe.API do end end + @spec add_telemetry_metadata(list, map) :: list + defp add_telemetry_metadata(opts, args) do + parsed_uri = URI.parse(args.req_url) + api_version = args.req_headers["Stripe-Version"] + + opts + |> Keyword.put(:telemetry_metadata, %{ + stripe_api_endpoint: parsed_uri.path, + stripe_api_version: api_version, + http_method: args.method, + http_retry_count: 0, + http_status_code: nil, + http_url: %{parsed_uri | query: nil} |> URI.to_string() + }) + end + @doc """ A low level utility function to make a direct request to the Stripe API @@ -329,6 +345,11 @@ defmodule Stripe.API do |> add_default_options() |> add_pool_option() |> add_options_from_config() + |> add_telemetry_metadata(%{ + method: method, + req_headers: req_headers, + req_url: req_url + }) do_perform_request(method, req_url, req_headers, req_body, req_opts) end @@ -353,6 +374,11 @@ defmodule Stripe.API do |> add_default_options() |> add_pool_option() |> add_options_from_config() + |> add_telemetry_metadata(%{ + method: method, + req_headers: req_headers, + req_url: req_url + }) do_perform_request(method, req_url, req_headers, body, req_opts) end @@ -376,19 +402,13 @@ defmodule Stripe.API do end defp do_perform_request_and_retry(method, url, headers, body, opts, {:attempts, attempts}) do - telemetry_meta = %{ - endpoint: URI.parse(url).path, - method: method, - attempt: attempts, - stripe_api_version: headers["Stripe-Version"], - status: nil - } + telemetry_meta = Keyword.get(opts, :telemetry_metadata) response = :telemetry.span(~w[stripe request]a, telemetry_meta, fn -> case http_module().request(method, url, Map.to_list(headers), body, opts) do {:ok, status, _, _} = resp -> - {resp, %{telemetry_meta | status: status}} + {resp, %{telemetry_meta | http_status_code: status, http_retry_count: attempts}} error -> {error, telemetry_meta} diff --git a/test/stripe/api_test.exs b/test/stripe/api_test.exs index 1937bdd2..c7ffaaad 100644 --- a/test/stripe/api_test.exs +++ b/test/stripe/api_test.exs @@ -115,14 +115,18 @@ defmodule Stripe.APITest do [:stripe, :request, :stop], %{monotonic_time: _, duration: _}, %{ - telemetry_span_context: _, - endpoint: "/v1/customers/search", - attempt: 0, - method: :get, - status: 200, - stripe_api_version: _ + http_method: :get, + http_retry_count: 0, + http_status_code: 200, + http_url: http_url, + stripe_api_version: _, + stripe_api_endpoint: "/v1/customers/search", + telemetry_span_context: _ } }) + + assert String.ends_with?(http_url, "/v1/customers/search") + assert not String.contains?(http_url, "test@example.com") end end