Add request_begin instrumentation callback (#902)

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.
This commit is contained in:
Brandur 2020-02-10 14:22:58 -08:00 committed by GitHub
parent 7182ae0f8b
commit 81407b6807
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 186 additions and 28 deletions

View File

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

View File

@ -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

View File

@ -450,19 +450,26 @@ module Stripe
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 @@ module Stripe
# 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 @@ module Stripe
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 @@ module Stripe
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 @@ module Stripe
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,

View File

@ -44,14 +44,27 @@ module Stripe
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?)

View File

@ -1150,9 +1150,23 @@ module Stripe
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 @@ module Stripe
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 @@ module Stripe
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 @@ module Stripe
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