small updates to Telemetry

.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:
@@ -38,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
@@ -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

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,14 +402,16 @@ defmodule Stripe.API do
  end
 
  defp do_perform_request_and_retry(method, url, headers, body, opts, {:attempts, attempts}) do
+ telemetry_meta = Keyword.get(opts, :telemetry_metadata)
+
  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 | http_status_code: status, http_retry_count: attempts}}
 
  error ->
- {error, %{}}
+ {error, telemetry_meta}
  end
  end)
 

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)

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,45 @@ 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: "[email protected]"|}
+ |> 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: _},
+ %{
+ 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, "[email protected]")
+ end
+ end
+
  @tag :skip
  test "gets default api version" do
  Stripe.API.request(%{}, :get, "products", %{}, [])

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

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

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