Move to monotonic time for duration calculations (#857)

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.

lib/stripe/connection_manager.rb

@@ -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 @@ def execute_request(method, uri, body: nil, headers: nil, query: nil)
       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)
 

lib/stripe/stripe_client.rb

@@ -9,7 +9,7 @@ class StripeClient
     # 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 @@ def self.current_thread_context
     # 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 @@ def self.maybe_gc_connection_managers
       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 @@ def self.maybe_gc_connection_managers
     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 @@ def self.maybe_gc_connection_managers
         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 @@ def self.maybe_gc_connection_managers
       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 @@ def self.maybe_gc_connection_managers
 
     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,

lib/stripe/util.rb

@@ -172,6 +172,19 @@ def self.flatten_params_array(value, calculated_key)
       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

test/stripe/connection_manager_test.rb

@@ -10,10 +10,9 @@ class ConnectionManagerTest < Test::Unit::TestCase
 
     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 @@ class ConnectionManagerTest < Test::Unit::TestCase
         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

test/stripe/stripe_client_test.rb

@@ -27,47 +27,63 @@ class StripeClientTest < Test::Unit::TestCase
         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 @@ class StripeClientTest < Test::Unit::TestCase
 
       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