Add request_begin instrumentation callback

Adds a new instrumentation callback called `request_begin` which, as the
name suggests, is invoked before an HTTP request is dispatched. As
outlined originally in #900, the idea is that this will enable a set of
hooks that can be used for distributed tracing.

The PR also renames the existing `request` callback to `request_end`,
although the old name is still invoked for the time being for backwards
compatibility.

A special `user_data` property is passed to `request_begin` which allows
subscribers to set custom data that will be passed through to
`request_end` for any given request. This allows, for example, a user
assigned ID to be set for the request and recognized on both ends.

I chose the naming `_begin` and `_end` (as opposed to start/finish or
any other combination) based on the naming conventions of Ruby itself.

Fixes #900.

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],

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

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,

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

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