Add simple instrumentation callback

We used to insert Faraday::Request::Instrumentation into our Faraday middleware
stack to be able to instrument Stripe calls with StatsD. With Faraday being
removed in version 5, this required some rework. This commit implements a simple
callback system that can be used with any kind of instrumentation system.

README.md

@@ -203,6 +203,23 @@ There are a few options for enabling it:
    Stripe.log_level = Stripe::LEVEL_INFO
    ```
 
+### Instrumentation
+
+The library has a hook for when a HTTP call is made which can be used for
+monitoring. The callback supplies the following arguments about the request:
+- the `RequestLogContext` object, if possible updated with response data
+- HTTP response code (`Integer`) if available, or `nil`
+- request duration in seconds (`Float`)
+
+For example:
+```ruby
+Stripe::Instrumentation.subscribe do |context, response_code, duration|
+  resource = context.path.split("/")[2]
+  tags = { method: context.method, resource: resource, code: response_code }
+  StatsD.distribution('stripe_request', duration, tags: tags)
+end
+```
+
 ### Writing a Plugin
 
 If you're writing a plugin that uses the library, we'd appreciate it if you

lib/stripe/instrumentation.rb

@@ -0,0 +1,23 @@
+# frozen_string_literal: true
+
+module Stripe
+  class Instrumentation
+    def self.subscribe(name = rand, &block)
+      subscribers[name] = block
+      name
+    end
+
+    def self.unsubscribe(name)
+      subscribers.delete(name)
+    end
+
+    def self.notify(*args)
+      subscribers.each_value { |subscriber| subscriber.call(*args) }
+    end
+
+    def self.subscribers
+      @subscribers ||= {}
+    end
+    private_class_method :subscribers
+  end
+end

lib/stripe/stripe_client.rb

@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+require "stripe/instrumentation"
+
 module Stripe
   # StripeClient executes requests against the Stripe API and allows a user to
   # recover both a resource a call returns as well as a response object that
@@ -452,15 +454,17 @@ def self.maybe_gc_connection_managers
         request_start = Util.monotonic_time
         log_request(context, num_retries)
         resp = yield
+        request_duration = Util.monotonic_time - request_start
+        response_code = resp.code.to_i
         context = context.dup_from_response_headers(resp)
+        Stripe::Instrumentation.notify(context, response_code, request_duration)
 
-        handle_error_response(resp, context) if resp.code.to_i >= 400
+        handle_error_response(resp, context) if response_code >= 400
 
-        log_response(context, request_start, resp.code.to_i, resp.body)
+        log_response(context, request_start, response_code, resp.body)
 
         if Stripe.enable_telemetry? && context.request_id
-          request_duration_ms =
-            ((Util.monotonic_time - request_start) * 1000).to_int
+          request_duration_ms = (request_duration * 1000).to_i
           @last_request_metrics =
             StripeRequestMetrics.new(context.request_id, request_duration_ms)
         end
@@ -472,15 +476,25 @@ def self.maybe_gc_connection_managers
         # If we modify context we copy it into a new variable so as not to
         # taint the original on a retry.
         error_context = context
+        request_duration = Util.monotonic_time - request_start
+        response_code = nil
 
         if e.is_a?(Stripe::StripeError)
           error_context = context.dup_from_response_headers(e.http_headers)
+          response_code = resp.code.to_i
           log_response(error_context, request_start,
                        e.http_status, e.http_body)
         else
           log_response_error(error_context, request_start, e)
         end
 
+        Stripe::Instrumentation.notify(
+          error_context,
+          response_code,
+          request_duration,
+          num_retries
+        )
+
         if self.class.should_retry?(e, method: method, num_retries: num_retries)
           num_retries += 1
           sleep self.class.sleep_time(num_retries)

test/stripe/stripe_client_test.rb

@@ -1144,6 +1144,82 @@ class StripeClientTest < Test::Unit::TestCase
         assert(!trace_payload["last_request_metrics"]["request_duration_ms"].nil?)
       end
     end
+
+    context "instrumentation" do
+      teardown do
+        Stripe::Instrumentation.send(:subscribers).clear
+      end
+
+      should "notify a subscriber of a successful HTTP request" do
+        events = []
+        Stripe::Instrumentation.subscribe { |*args| events << args }
+
+        stub_request(:get, "#{Stripe.api_base}/v1/charges")
+          .to_return(body: JSON.generate(object: "charge"))
+
+        Stripe::Charge.list
+
+        assert_equal(1, events.size)
+        event = events.first
+        assert_equal(:get, event[0].method)
+        assert_equal("/v1/charges", event[0].path)
+        assert_equal(200, event[1])
+        assert(event[2].positive?)
+      end
+
+      should "notify a subscriber of a StripeError" do
+        events = []
+        Stripe::Instrumentation.subscribe { |*args| events << args }
+
+        error = {
+          code: "code",
+          message: "message",
+          param: "param",
+          type: "type",
+        }
+        stub_request(:get, "#{Stripe.api_base}/v1/charges")
+          .to_return(
+            body: JSON.generate(error: error),
+            status: 500
+          )
+
+        assert_raises(Stripe::APIError) do
+          Stripe::Charge.list
+        end
+
+        assert_equal(2, events.size)
+        first_event = events.first
+        assert_equal(:get, first_event[0].method)
+        assert_equal("/v1/charges", first_event[0].path)
+        assert_equal(500, first_event[1])
+        assert(first_event[2].positive?)
+
+        second_event = events.last
+        assert_equal(:get, second_event[0].method)
+        assert_equal("/v1/charges", second_event[0].path)
+        assert_equal(500, second_event[1])
+        assert(second_event[2].positive?)
+      end
+
+      should "notify a subscriber of a network error" do
+        events = []
+        Stripe::Instrumentation.subscribe { |*args| events << args }
+
+        stub_request(:get, "#{Stripe.api_base}/v1/charges")
+          .to_raise(Net::OpenTimeout)
+
+        assert_raises(Stripe::APIConnectionError) do
+          Stripe::Charge.list
+        end
+
+        assert_equal(1, events.size)
+        event = events.first
+        assert_equal(:get, event[0].method)
+        assert_equal("/v1/charges", event[0].path)
+        assert_nil(event[1])
+        assert(event[2].positive?)
+      end
+    end
   end
 
   class SystemProfilerTest < Test::Unit::TestCase