sharpetronics/stripe-ruby
1
0
Fork 0
mirror of https://github.com/stripe/stripe-ruby.git synced 2025-06-03 00:01:47 -04:00
Code Issues Projects Releases Wiki Activity

Move to monotonic time for duration calculations (#857)

Browse Source 
Drops the use of `Time.now` in favor of using the system's monotonic
clock for various operations that calculate and use elapsed duration.
The latter is preferable because in some cases `Time.now` can be
unstable, like if it's set manually by a system administrator or an NTP
daemon.

I don't expect that the previous code would actually have caused trouble
in the vast majority of normal situations, so I'm not going to backport
anything, but this seems like good hygiene.

For better or worse I had to wrap the monotonic time calls in a new
`Util` function because (1) the normal invocation is long enough to have
caused a lot of overruns on our 80 character line lengths, and (2)
Timecop doesn't stub the monotonic clock, so the `Util` method gives us
a nice place that we can stub on where necessary.
This commit is contained in:
Brandur 2019-10-01 09:58:50 -07:00 committed by Brandur
parent f2b1fa150c
commit 480303c446
5 changed files with 84 additions and 61 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

11
lib/stripe/connection_manager.rb
View File

@ -10,14 +10,15 @@ module Stripe
# Note that this class in itself is *not* thread safe. We expect it to be
# instantiated once per thread.
class ConnectionManager
# Timestamp indicating when the connection manager last made a request.
# This is used by `StripeClient` to determine whether a connection manager
# should be garbage collected or not.
# Timestamp (in seconds procured from the system's monotonic clock)
# indicating when the connection manager last made a request. This is used
# by `StripeClient` to determine whether a connection manager should be
# garbage collected or not.
attr_reader :last_used
def initialize
@active_connections = {}
@last_used = Time.now
@last_used = Util.monotonic_time
# A connection manager may be accessed across threads as one thread makes
# requests on it while another is trying to clear it (either because it's
@ -78,7 +79,7 @@ module Stripe
raise ArgumentError, "query should be a string" \
if query && !query.is_a?(String)
@last_used = Time.now
@last_used = Util.monotonic_time
connection = connection_for(uri)

21
lib/stripe/stripe_client.rb
View File

@ -9,7 +9,7 @@ module Stripe
# synchronize global access to them.
@thread_contexts_with_connection_managers = []
@thread_contexts_with_connection_managers_mutex = Mutex.new
@last_connection_manager_gc = Time.now
@last_connection_manager_gc = Util.monotonic_time
# Initializes a new `StripeClient`.
#
@ -368,11 +368,11 @@ module Stripe
# For internal use only. Does not provide a stable API and may be broken
# with future non-major changes.
def self.maybe_gc_connection_managers
if @last_connection_manager_gc + CONNECTION_MANAGER_GC_PERIOD > Time.now
return nil
end
next_gc_time = @last_connection_manager_gc + CONNECTION_MANAGER_GC_PERIOD
return nil if next_gc_time > Util.monotonic_time
last_used_threshold = Time.now - CONNECTION_MANAGER_GC_LAST_USED_EXPIRY
last_used_threshold =
Util.monotonic_time - CONNECTION_MANAGER_GC_LAST_USED_EXPIRY
pruned_thread_contexts = []
@thread_contexts_with_connection_managers.each do |thread_context|
@ -385,7 +385,7 @@ module Stripe
end
@thread_contexts_with_connection_managers -= pruned_thread_contexts
@last_connection_manager_gc = Time.now
@last_connection_manager_gc = Util.monotonic_time
pruned_thread_contexts.count
end
@ -445,7 +445,7 @@ module Stripe
private def execute_request_with_rescues(method, api_base, context)
num_retries = 0
begin
request_start = Time.now
request_start = Util.monotonic_time
log_request(context, num_retries)
resp = yield
context = context.dup_from_response_headers(resp)
@ -455,7 +455,8 @@ module Stripe
log_response(context, request_start, resp.code.to_i, resp.body)
if Stripe.enable_telemetry? && context.request_id
request_duration_ms = ((Time.now - request_start) * 1000).to_int
request_duration_ms =
((Util.monotonic_time - request_start) * 1000).to_int
@last_request_metrics =
StripeRequestMetrics.new(context.request_id, request_duration_ms)
end
@ -726,7 +727,7 @@ module Stripe
Util.log_info("Response from Stripe API",
account: context.account,
api_version: context.api_version,
elapsed: Time.now - request_start,
elapsed: Util.monotonic_time - request_start,
idempotency_key: context.idempotency_key,
method: context.method,
path: context.path,
@ -748,7 +749,7 @@ module Stripe
private def log_response_error(context, request_start, error)
Util.log_error("Request error",
elapsed: Time.now - request_start,
elapsed: Util.monotonic_time - request_start,
error_message: error.message,
idempotency_key: context.idempotency_key,
method: context.method,

13
lib/stripe/util.rb
View File

@ -172,6 +172,19 @@ module Stripe
result
end
# `Time.now` can be unstable in cases like an administrator manually
# updating its value or a reconcilation via NTP. For this reason, prefer
# the use of the system's monotonic clock especially where comparing times
# to calculate an elapsed duration.
#
# Shortcut for getting monotonic time, mostly for purposes of line length
# and stubbing (Timecop doesn't freeze the monotonic clock). Returns time
# in seconds since the event used for monotonic reference purposes by the
# platform (e.g. system boot time).
def self.monotonic_time
Process.clock_gettime(Process::CLOCK_MONOTONIC)
end
def self.normalize_id(id)
if id.is_a?(Hash) # overloaded id
params_hash = id.dup

27
test/stripe/connection_manager_test.rb
View File

@ -10,10 +10,9 @@ module Stripe
context "#initialize" do
should "set #last_used to current time" do
t = Time.new(2019)
Timecop.freeze(t) do
assert_equal t, Stripe::ConnectionManager.new.last_used
end
t = 123.0
Util.stubs(:monotonic_time).returns(t)
assert_equal t, Stripe::ConnectionManager.new.last_used
end
end
@ -147,19 +146,17 @@ module Stripe
stub_request(:post, "#{Stripe.api_base}/path")
.to_return(body: JSON.generate(object: "account"))
t = Time.new(2019)
t = 123.0
Util.stubs(:monotonic_time).returns(t)
# Make sure the connection manager is initialized at a different time
# than the one we're going to measure at because `#last_used` is also
# set by the constructor.
manager = Timecop.freeze(t) do
Stripe::ConnectionManager.new
end
manager = Stripe::ConnectionManager.new
Timecop.freeze(t + 1) do
manager.execute_request(:post, "#{Stripe.api_base}/path")
assert_equal t + 1, manager.last_used
end
# `#last_used` is also set by the constructor, so make sure we get a
# new value for it.
Util.stubs(:monotonic_time).returns(t + 1.0)
manager.execute_request(:post, "#{Stripe.api_base}/path")
assert_equal t + 1.0, manager.last_used
end
end
end

73
test/stripe/stripe_client_test.rb
View File

@ -27,47 +27,63 @@ module Stripe
StripeClient.clear_all_connection_managers
# Establish a base time.
t = Time.new(2019)
t = 0.0
# And pretend that `StripeClient` was just initialized for the first
# time. (Don't access instance variables like this, but it's tricky to
# test properly otherwise.)
StripeClient.instance_variable_set(:@last_connection_manager_gc, t)
Timecop.freeze(t) do
# Execute an initial request to ensure that a connection manager was
# created.
client = StripeClient.new
client.execute_request(:post, "/v1/path")
#
# t
#
Util.stubs(:monotonic_time).returns(t)
# The GC shouldn't run yet (a `nil` return indicates that GC didn't run).
assert_equal nil, StripeClient.maybe_gc_connection_managers
end
# Execute an initial request to ensure that a connection manager was
# created.
client = StripeClient.new
client.execute_request(:post, "/v1/path")
# The GC shouldn't run yet (a `nil` return indicates that GC didn't run).
assert_equal nil, StripeClient.maybe_gc_connection_managers
#
# t + StripeClient::CONNECTION_MANAGER_GC_PERIOD - 1
#
# Move time to just *before* garbage collection is eligible to run.
# Nothing should happen.
Timecop.freeze(t + StripeClient::CONNECTION_MANAGER_GC_PERIOD - 1) do
assert_equal nil, StripeClient.maybe_gc_connection_managers
end
#
Util.stubs(:monotonic_time).returns(t + StripeClient::CONNECTION_MANAGER_GC_PERIOD - 1)
assert_equal nil, StripeClient.maybe_gc_connection_managers
#
# t + StripeClient::CONNECTION_MANAGER_GC_PERIOD + 1
#
# Move time to just *after* garbage collection is eligible to run.
# Garbage collection will run, but because the connection manager is
# not passed its expiry age, it will not be collected. Zero is returned
# to indicate so.
Timecop.freeze(t + StripeClient::CONNECTION_MANAGER_GC_PERIOD + 1) do
assert_equal 0, StripeClient.maybe_gc_connection_managers
end
#
Util.stubs(:monotonic_time).returns(t + StripeClient::CONNECTION_MANAGER_GC_PERIOD + 1)
assert_equal 0, StripeClient.maybe_gc_connection_managers
#
# t + StripeClient::CONNECTION_MANAGER_GC_LAST_USED_EXPIRY + 1
#
# Move us far enough into the future that we're passed the horizons for
# both a GC run as well as well as the expiry age of a connection
# manager. That means the GC will run and collect the connection
# manager that we created above.
Timecop.freeze(t + StripeClient::CONNECTION_MANAGER_GC_LAST_USED_EXPIRY + 1) do
assert_equal 1, StripeClient.maybe_gc_connection_managers
#
Util.stubs(:monotonic_time).returns(t + StripeClient::CONNECTION_MANAGER_GC_LAST_USED_EXPIRY + 1)
# And as an additional check, the connection manager of the current thread context should have been set to `nil` as it was GCed.
assert_nil StripeClient.current_thread_context.default_connection_manager
end
assert_equal 1, StripeClient.maybe_gc_connection_managers
# And as an additional check, the connection manager of the current
# thread context should have been set to `nil` as it was GCed.
assert_nil StripeClient.current_thread_context.default_connection_manager
end
end
@ -300,17 +316,12 @@ module Stripe
context "logging" do
setup do
# Freeze time for the purposes of the `elapsed` parameter that we
# emit for responses. I didn't want to bring in a new dependency for
# this, but Mocha's `anything` parameter can't match inside of a hash
# and is therefore not useful for this purpose. If we switch over to
# rspec-mocks at some point, we can probably remove Timecop from the
# project.
Timecop.freeze(Time.local(1990))
end
teardown do
Timecop.return
# Freeze time for the purposes of the `elapsed` parameter that we emit
# for responses. Mocha's `anything` parameter can't match inside of a
# hash and is therefore not useful for this purpose, and Timecop
# doesn't freeze monotonic time. If we switch over to rspec-mocks at
# some point, we can probably remove Timecop from the project.
Util.stubs(:monotonic_time).returns(0.0)
end
should "produce appropriate logging" do