diff --git a/README.md b/README.md index 88b64414a..b9dd3b647 100644 --- a/README.md +++ b/README.md @@ -219,21 +219,43 @@ There are a few options for enabling it: ### Instrumentation -The library has a hook for when a HTTP call is made which can be used for -monitoring. The callback receives a `RequestEvent` object with the following -data: +The library has various hooks that user code can tie into by passing a block to +`Stripe::Instrumentation.subscribe` to be notified about specific events. -- HTTP method (`Symbol`) -- request path (`String`) -- HTTP response code (`Integer`) if available, or `nil` in case of a lower - level network error -- request duration in seconds (`Float`) -- the number of retries (`Integer`) +#### `request_begin` + +Invoked when an HTTP request starts. Receives `RequestBeginEvent` with the +following properties: + +- `method`: HTTP method. (`Symbol`) +- `num_retries`: The number of retries. (`Integer`) +- `user_data`: A hash on which users can set arbitrary data, and which will be + passed through to `request_end` invocations. This could be used, for example, + to assign unique IDs to each request, and it'd work even if many requests are + running in parallel. All subscribers share the same object for any particular + request, so they must be careful to use unique keys that will not conflict + with other subscribers. (`Hash`) + +#### `request_end` + +Invoked when an HTTP request finishes, regardless of whether it terminated with +a success or error. Receives `RequestEndEvent` with the following properties: + +- `duration`: Request duration in seconds. (`Float`) +- `http_status`: HTTP response code (`Integer`) if available, or `nil` in case + of a lower level network error. +- `method`: HTTP method. (`Symbol`) +- `num_retries`: The number of retries. (`Integer`) +- `path`: Request path. (`String`) +- `user_data`: A hash on which users may have set arbitrary data in + `request_begin`. See above for more information. (`Hash`) + +#### Example For example: ```ruby -Stripe::Instrumentation.subscribe(:request) do |request_event| +Stripe::Instrumentation.subscribe(:request_end) do |request_event| tags = { method: request_event.method, resource: request_event.path.split("/")[2], diff --git a/lib/stripe/instrumentation.rb b/lib/stripe/instrumentation.rb index df9f686b9..3eee014bf 100644 --- a/lib/stripe/instrumentation.rb +++ b/lib/stripe/instrumentation.rb @@ -2,23 +2,65 @@ module Stripe class Instrumentation - class RequestEvent + # Event emitted on `request_begin` callback. + class RequestBeginEvent + attr_reader :method + attr_reader :path + + # Arbitrary user-provided data in the form of a Ruby hash that's passed + # from subscribers on `request_begin` to subscribers on `request_end`. + # `request_begin` subscribers can set keys which will then be available + # in `request_end`. + # + # Note that all subscribers of `request_begin` share the same object, so + # they must be careful to set unique keys so as to not conflict with data + # set by other subscribers. + attr_reader :user_data + + def initialize(method:, path:, user_data:) + @method = method + @path = path + @user_data = user_data + freeze + end + end + + # Event emitted on `request_end` callback. + class RequestEndEvent attr_reader :duration attr_reader :http_status attr_reader :method attr_reader :num_retries attr_reader :path - def initialize(duration:, http_status:, method:, num_retries:, path:) + # Arbitrary user-provided data in the form of a Ruby hash that's passed + # from subscribers on `request_begin` to subscribers on `request_end`. + # `request_begin` subscribers can set keys which will then be available + # in `request_end`. + attr_reader :user_data + + def initialize(duration:, http_status:, method:, num_retries:, path:, + user_data: nil) @duration = duration @http_status = http_status @method = method @num_retries = num_retries @path = path + @user_data = user_data freeze end end + # This class was renamed for consistency. This alias is here for backwards + # compatibility. + RequestEvent = RequestEndEvent + + # Returns true if there are a non-zero number of subscribers on the given + # topic, and false otherwise. + def self.any_subscribers?(topic) + !subscribers[topic].empty? + end + def self.subscribe(topic, name = rand, &block) subscribers[topic][name] = block name diff --git a/lib/stripe/stripe_client.rb b/lib/stripe/stripe_client.rb index d5fca50a0..48ee67fcd 100644 --- a/lib/stripe/stripe_client.rb +++ b/lib/stripe/stripe_client.rb @@ -450,19 +450,26 @@ def self.maybe_gc_connection_managers private def execute_request_with_rescues(method, api_base, context) num_retries = 0 + begin - request_start = Util.monotonic_time + request_start = nil + user_data = nil + log_request(context, num_retries) + user_data = notify_request_begin(context) + + request_start = Util.monotonic_time resp = yield request_duration = Util.monotonic_time - request_start + http_status = resp.code.to_i context = context.dup_from_response_headers(resp) handle_error_response(resp, context) if http_status >= 400 log_response(context, request_start, http_status, resp.body) - notify_subscribers(request_duration, http_status, context, - num_retries) + notify_request_end(context, request_duration, http_status, + num_retries, user_data) if Stripe.enable_telemetry? && context.request_id request_duration_ms = (request_duration * 1000).to_i @@ -477,8 +484,8 @@ 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 http_status = nil + request_duration = Util.monotonic_time - request_start if request_start if e.is_a?(Stripe::StripeError) error_context = context.dup_from_response_headers(e.http_headers) @@ -488,7 +495,8 @@ def self.maybe_gc_connection_managers else log_response_error(error_context, request_start, e) end - notify_subscribers(request_duration, http_status, context, num_retries) + notify_request_end(context, request_duration, http_status, num_retries, + user_data) if self.class.should_retry?(e, method: method, num_retries: num_retries) num_retries += 1 @@ -512,15 +520,39 @@ def self.maybe_gc_connection_managers resp end - private def notify_subscribers(duration, http_status, context, num_retries) - request_event = Instrumentation::RequestEvent.new( + private def notify_request_begin(context) + return unless Instrumentation.any_subscribers?(:request_begin) + + event = Instrumentation::RequestBeginEvent.new( + method: context.method, + path: context.path, + user_data: {} + ) + Stripe::Instrumentation.notify(:request_begin, event) + + # This field may be set in the `request_begin` callback. If so, we'll + # forward it onto `request_end`. + event.user_data + end + + private def notify_request_end(context, duration, http_status, num_retries, + user_data) + return if !Instrumentation.any_subscribers?(:request_end) && + !Instrumentation.any_subscribers?(:request) + + event = Instrumentation::RequestEndEvent.new( duration: duration, http_status: http_status, method: context.method, num_retries: num_retries, - path: context.path + path: context.path, + user_data: user_data || {} ) - Stripe::Instrumentation.notify(:request, request_event) + Stripe::Instrumentation.notify(:request_end, event) + + # The name before `request_begin` was also added. Provided for backwards + # compatibility. + Stripe::Instrumentation.notify(:request, event) end private def general_api_error(status, body) @@ -772,8 +804,9 @@ def self.maybe_gc_connection_managers end private def log_response_error(context, request_start, error) + elapsed = request_start ? Util.monotonic_time - request_start : nil Util.log_error("Request error", - elapsed: Util.monotonic_time - request_start, + elapsed: elapsed, error_message: error.message, idempotency_key: context.idempotency_key, method: context.method, diff --git a/test/stripe/instrumentation_test.rb b/test/stripe/instrumentation_test.rb index c8eec9ce0..27611f5fc 100644 --- a/test/stripe/instrumentation_test.rb +++ b/test/stripe/instrumentation_test.rb @@ -44,14 +44,27 @@ class InstrumentationTest < Test::Unit::TestCase end end - context "RequestEvent" do + context "RequestEventBegin" do should "return a frozen object" do - event = Stripe::Instrumentation::RequestEvent.new( + event = Stripe::Instrumentation::RequestBeginEvent.new( + method: :get, + path: "/v1/test", + user_data: nil + ) + + assert(event.frozen?) + end + end + + context "RequestEventEnd" do + should "return a frozen object" do + event = Stripe::Instrumentation::RequestEndEvent.new( duration: 0.1, http_status: 200, method: :get, num_retries: 0, - path: "/v1/test" + path: "/v1/test", + user_data: nil ) assert(event.frozen?) diff --git a/test/stripe/stripe_client_test.rb b/test/stripe/stripe_client_test.rb index 73c2ddf95..c00ed510d 100644 --- a/test/stripe/stripe_client_test.rb +++ b/test/stripe/stripe_client_test.rb @@ -1150,9 +1150,23 @@ class StripeClientTest < Test::Unit::TestCase Stripe::Instrumentation.unsubscribe(:request, :test) end + should "notify a subscribe on HTTP request start" do + events = [] + Stripe::Instrumentation.subscribe(:request_end, :test) { |event| events << event } + + 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.method) + assert_equal("/v1/charges", event.path) + end + should "notify a subscriber of a successful HTTP request" do events = [] - Stripe::Instrumentation.subscribe(:request, :test) { |event| events << event } + Stripe::Instrumentation.subscribe(:request_end, :test) { |event| events << event } stub_request(:get, "#{Stripe.api_base}/v1/charges") .to_return(body: JSON.generate(object: "charge")) @@ -1169,7 +1183,7 @@ class StripeClientTest < Test::Unit::TestCase should "notify a subscriber of a StripeError" do events = [] - Stripe::Instrumentation.subscribe(:request, :test) { |event| events << event } + Stripe::Instrumentation.subscribe(:request_end, :test) { |event| events << event } error = { code: "code", @@ -1197,7 +1211,7 @@ class StripeClientTest < Test::Unit::TestCase should "notify a subscriber of a network error" do events = [] - Stripe::Instrumentation.subscribe(:request, :test) { |event| events << event } + Stripe::Instrumentation.subscribe(:request_end, :test) { |event| events << event } stub_request(:get, "#{Stripe.api_base}/v1/charges") .to_raise(Net::OpenTimeout) @@ -1213,6 +1227,40 @@ class StripeClientTest < Test::Unit::TestCase assert(event.duration.positive?) assert_equal(0, event.num_retries) end + + should "pass `user_data` from `request_begin` to `request_end`" do + actual_user_data = nil + + Stripe::Instrumentation.subscribe(:request_begin) do |event| + event.user_data[:foo] = :bar + end + Stripe::Instrumentation.subscribe(:request_end) do |event| + actual_user_data = event.user_data + end + + stub_request(:get, "#{Stripe.api_base}/v1/charges") + .to_return(body: JSON.generate(object: "charge")) + Stripe::Charge.list + + assert_equal({ foo: :bar }, actual_user_data) + end + + should "provide backward compatibility on `request` topic" do + events = [] + Stripe::Instrumentation.subscribe(:request, :test) { |event| events << event } + + 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.method) + assert_equal("/v1/charges", event.path) + assert_equal(200, event.http_status) + assert(event.duration.positive?) + assert_equal(0, event.num_retries) + end end end