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

@@ -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)
 

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,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: "[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: _},
+        %{
+          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", %{}, [])

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

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