Feat: Emit [:stripity_stripe, :request, :start|:stop] telemetry

lib/stripe/api.ex

@@ -380,8 +380,11 @@ defmodule Stripe.API do
   end
 
   defp do_perform_request_and_retry(method, url, headers, body, opts, {:attempts, attempts}) do
-    log_request(method, url, headers, attempts)
-    response = http_module().request(method, url, headers, body, opts)
+    {idempotency_key, attempt} = log_request(method, url, headers, attempts)
+
+    response = track_request_time(method, url, idempotency_key, attempt,
+      fn -> http_module().request(method, url, headers, body, opts) end
+    )
 
     do_perform_request_and_retry(
       method,
@@ -393,6 +396,25 @@ defmodule Stripe.API do
     )
   end
 
+  defp track_request_time(method, url, idempotency_key, attempt, request_fn) do
+    start_metadata = %{
+      method: method,
+      url: url,
+      idempotency_key: idempotency_key,
+      attempt: attempt
+    }
+
+    :telemetry.span([:stripity_stripe, :request],
+      start_metadata,
+      fn ->
+        result = request_fn.()
+
+        # we don't produce any more metadata to add to the span, hence the empty map
+        {result, %{}}
+      end
+    )
+  end
+
   defp log_request(method, url, headers, attempts) do
     http_method_url = "'#{String.upcase(to_string(method))} #{url}'"
 
@@ -403,6 +425,8 @@ defmodule Stripe.API do
     attempt = "attempt=#{attempts + 1}"
 
     Logger.info("[stripity_stripe] Performing #{http_method_url} #{attempt}#{idempotency_key_msg}")
+
+    {idempotency_key, attempts+1}
   end
 
   defp get_idempotency_key_from_headers(method, _headers) when method in [:get, :headers], do: nil

test/stripe/telemetry_test.exs

@@ -0,0 +1,37 @@
+defmodule Stripe.TelemetryTest do
+  use Stripe.StripeCase, async: true
+
+  test "telemetry" do
+    test_process = self()
+
+    :ok =
+      :telemetry.attach_many(
+        "telemetry-test",
+        [
+          [:stripity_stripe, :request, :start],
+          [:stripity_stripe, :request, :stop]
+        ],
+        fn name, measurements, _metadata, _ ->
+          cond do
+            :start in name ->
+              send(test_process, :request_started)
+
+            :stop in name ->
+              send(test_process, {:request_stopped, measurements.duration})
+          end
+        end,
+        nil
+      )
+
+    assert {:ok, %Stripe.Charge{}} = Stripe.Charge.update("ch_123", %{metadata: %{foo: "bar"}})
+    assert_stripe_requested(:post, "/v1/charges/ch_123")
+
+    assert_receive :request_started,
+                   200,
+                   "[:request, :start] telemetry event wasn't emitted after 200ms"
+
+    assert_receive {:request_stopped, duration} when is_integer(duration),
+                   200,
+                   "[:request, :stop] telemetry event wasn't emitted after 200ms"
+  end
+end