diff --git a/lib/stripe/api.ex b/lib/stripe/api.ex index 2968963c..0ee346a6 100644 --- a/lib/stripe/api.ex +++ b/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 diff --git a/test/stripe/telemetry_test.exs b/test/stripe/telemetry_test.exs new file mode 100644 index 00000000..fc0a7cbc --- /dev/null +++ b/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