Log rate limit events

This commit adds logging when a client is rate throttled. It emits a log to stdout by default and there is a configurable logging block that is made available so that developers can push to a custom endpoint such as honeycomb.


Co-authored-by: Lola Odelola <damzcodes@gmail.com>

README.md

@@ -318,6 +318,14 @@ To disable this retry and sleep behavior set the env var`PLATFORM_API_DISABLE_RA
 
 For more information about this algorithm and behavior see [Rate Limit GCRA client demo](https://github.com/schneems/rate-limit-gcra-client-demo).
 
+By default rate throttling will log to STDOUT when the sleep/retry behavior is triggered. To add your own custom logging, for example to librato or honeycomb, you can pass in a callable object that takes three arguments:
+
+```ruby
+PlatformAPI.rate_throttle.log = ->(event_type, request, throttle_object) {
+  # Your logic here
+}
+```
+
 ## Building and releasing
 
 ### Generate a new client

config/client-config.rb

@@ -7,8 +7,13 @@
   config.base_url = 'https://api.heroku.com'
   config.module_name = 'PlatformAPI'
   config.schema_filepath = File.join(File.expand_path('../..', __FILE__), 'schema.json')
-  config.rate_throttle = PlatformAPI::HerokuClientThrottle.new unless ENV['PLATFORM_API_DISABLE_RATE_THROTTLE']
-  config.acceptable_status_codes = [429]
+
+  unless ENV['PLATFORM_API_DISABLE_RATE_THROTTLE']
+    PlatformAPI.rate_throttle = PlatformAPI::HerokuClientThrottle.new
+
+    config.rate_throttle = PlatformAPI.rate_throttle
+    config.acceptable_status_codes = [429]
+  end
 
   config.headers = {
     'Accept'      => 'application/vnd.heroku+json; version=3',

lib/platform-api.rb

@@ -1,11 +1,22 @@
 require 'heroics'
 require 'moneta'
 
-require_relative '../config/client-config'
 # Ruby HTTP client for the Heroku API.
 module PlatformAPI
+  def self.rate_throttle=(rate_throttle)
+    @rate_throttle = rate_throttle
+  end
+
+  # Get access to the rate throttling class object for configuration.
+  #
+  # @return [PlatformAPI::HerokuClientThrottle]
+  def self.rate_throttle
+    @rate_throttle
+  end
 end
 
+require_relative '../config/client-config'
+
 require 'platform-api/client'
 require 'platform-api/version'
 require 'platform-api/heroku_client_throttle'

lib/platform-api/heroku_client_throttle.rb

@@ -28,9 +28,10 @@ class HerokuClientThrottle
     MIN_SLEEP = 1/(MAX_LIMIT / 3600)
     MIN_SLEEP_OVERTIME_PERCENT = 1.0 - 0.9 # Allow min sleep to go lower than actually calculated value, must be less than 1
 
-    attr_reader :rate_limit_multiply_at, :sleep_for, :rate_limit_count, :log, :mutex
+    attr_reader :rate_limit_multiply_at, :sleep_for, :rate_limit_count, :mutex
+    attr_accessor :log
 
-    def initialize(log = ->(req, throttle) {})
+    def initialize
       @mutex = Mutex.new
       @sleep_for = 2 * MIN_SLEEP
       @rate_limit_count = 0
@@ -39,7 +40,7 @@ def initialize(log = ->(req, throttle) {})
       @min_sleep_bound = MIN_SLEEP * MIN_SLEEP_OVERTIME_PERCENT
       @rate_multiplier = 1
       @rate_limit_multiply_at = Time.now - 1800
-      @log = log
+      @log = ->(event, req, throttle) {}
     end
 
     def jitter
@@ -51,8 +52,6 @@ def call(&block)
 
       req = yield
 
-      log.call(req, self)
-
       if retry_request?(req)
         req = retry_request_logic(req, &block)
         return req
@@ -103,6 +102,9 @@ def retry_request_logic(req, &block)
           @times_retried += 1
           @retry_thread = Thread.current
         end
+
+        log.call(:retry_request, req, self)
+        puts "HerokuClientThrottle: event=retry_request process=#{Process.pid} thread=#{Thread.current.object_id} sleep_for=#{@sleep_for}"
       end
 
       # Retry the request with the new sleep value

spec/unit/heroku_client_throttle_spec.rb

@@ -15,6 +15,28 @@ def initialize(status = 200, remaining = 10)
 end
 
 describe 'Heroku client throttle' do
+  it "configuring logging works" do
+    client = PlatformAPI::HerokuClientThrottle.new
+
+    @log_count = 0
+    client.log = ->(event, request, throttle) { @log_count += 1 }
+
+    def client.sleep(val); end;
+
+    @times_called = 0
+    client.call do
+      @times_called += 1
+      if client.rate_limit_count < 2
+        FakeResponse.new(429)
+      else
+        FakeResponse.new
+      end
+    end
+
+    expect(@times_called).to eq(3) # Once for initial 429, once for second 429, once for final 200
+    expect(@log_count).to eq(2)
+  end
+
   it "Check when rate limit is triggered, the time since multiply changes" do
     client = PlatformAPI::HerokuClientThrottle.new
     def client.sleep(val); end;