diff --git a/.gitignore b/.gitignore index ab09e0c..fa7f8ae 100644 --- a/.gitignore +++ b/.gitignore @@ -2,3 +2,6 @@ Gemfile.lock .ruby-version coverage/ +.bundle/ +vendor/ +*-plan.md diff --git a/.rubocop_todo.yml b/.rubocop_todo.yml index c02e129..a046775 100644 --- a/.rubocop_todo.yml +++ b/.rubocop_todo.yml @@ -62,7 +62,7 @@ Lint/UnusedBlockArgument: # Offense count: 3 # Configuration parameters: AllowedMethods, AllowedPatterns, IgnoredMethods, CountRepeatedAttributes. Metrics/AbcSize: - Max: 25 + Max: 33 # Offense count: 3 # Configuration parameters: CountComments, CountAsOne, ExcludedMethods, AllowedMethods, AllowedPatterns, IgnoredMethods. @@ -73,7 +73,7 @@ Metrics/BlockLength: # Offense count: 1 # Configuration parameters: CountComments, CountAsOne. Metrics/ClassLength: - Max: 115 + Max: 167 # Offense count: 2 # Configuration parameters: AllowedMethods, AllowedPatterns, IgnoredMethods. @@ -83,7 +83,7 @@ Metrics/CyclomaticComplexity: # Offense count: 11 # Configuration parameters: CountComments, CountAsOne, ExcludedMethods, AllowedMethods, AllowedPatterns, IgnoredMethods. Metrics/MethodLength: - Max: 16 + Max: 21 # Offense count: 1 # This cop supports safe autocorrection (--autocorrect). diff --git a/History.md b/History.md index d07c50a..6abeb7a 100644 --- a/History.md +++ b/History.md @@ -1,3 +1,28 @@ +Unreleased +========== + +### Upgrade note: new request header and proxy allowlists + +This release sends an `X-Retry-Count` request header on retries. If your +traffic to Segment goes through a proxy, gateway or WAF that allowlists +request headers, add it before upgrading or retried uploads will be +rejected. The `Authorization` header is unchanged: this client has always +sent the write key as HTTP Basic credentials. + +* Send `X-Retry-Count` on retries, so the server can distinguish a retry from a first attempt. Omitted on the first attempt. +* Unified retry handling: 429, 408, 410, 460 and 5xx (except 501, 505 and 511) are retried. `Retry-After` is honoured on all of them, not just 429, which brings 529 in through the generic 5xx rule. +* `Retry-After` accepts numeric seconds and the RFC 7231 HTTP-date formats, capped at 300s (`rate_limit_retry_after_cap`). +* Rate-limited retries are bounded by elapsed time rather than counted against the retry limit, so a long `Retry-After` no longer exhausts the budget. +* New options `max_total_backoff_duration` and `max_rate_limit_duration` (default 12 hours each) bound the two waits. +* Only 2xx responses count as a successful upload. A 3xx is now reported as a failed upload rather than silently treated as delivered. It is not retried: a redirect `Net::HTTP` already declined to follow will not succeed on a retry. The Segment endpoint does not redirect, so this only affects custom `host` values. +* Network errors are retried on the same backoff schedule as failed responses instead of dropping the batch. +* Backoff waits no longer block shutdown for the full delay. +* Retry timing uses a monotonic clock, so a system clock change cannot stretch or collapse a backoff. +* Backoff intervals are now jittered at the ceiling as well, so clients that back off together do not retry in lockstep. +* **Default backoff pacing changed**: the base wait is 500ms (was 100ms), the ceiling is 60s (was 10s), and the multiplier is 2 (was 1.5). This aligns ruby with the other Segment SDKs, but it does mean a retry schedule that was previously 100ms, 150ms, 225ms… now starts at 500ms and climbs faster. Set `min_timeout_ms`, `max_timeout_ms` and `multiplier` on a `BackoffPolicy` to keep the old pacing. +* A `backoff_policy` supplied by the caller that does not implement `reset!` now logs a warning. One policy instance serves every batch, so without `reset!` its attempt count accumulates and retries get slower the longer the process runs. +* Fix `retries` granting one fewer attempt than configured. A configured 10 performed 9, and `retries: 1` performed none at all. + 2.5.0 / 2024-07-17 ================== diff --git a/e2e-cli/e2e-config.json b/e2e-cli/e2e-config.json index f0aea47..1bdb54a 100644 --- a/e2e-cli/e2e-config.json +++ b/e2e-cli/e2e-config.json @@ -1,7 +1,9 @@ { "sdk": "ruby", - "test_suites": "basic", + "test_suites": "basic,retry", "auto_settings": false, "patch": null, - "env": {} + "env": { + "AUTH_HEADER": "true" + } } diff --git a/lib/segment/analytics.rb b/lib/segment/analytics.rb index 707e7c4..37e3a2e 100644 --- a/lib/segment/analytics.rb +++ b/lib/segment/analytics.rb @@ -6,6 +6,7 @@ require 'segment/analytics/field_parser' require 'segment/analytics/client' require 'segment/analytics/worker' +require 'segment/analytics/retry_budget' require 'segment/analytics/transport' require 'segment/analytics/response' require 'segment/analytics/logging' diff --git a/lib/segment/analytics/backoff_policy.rb b/lib/segment/analytics/backoff_policy.rb index e6033b1..9f9bff1 100644 --- a/lib/segment/analytics/backoff_policy.rb +++ b/lib/segment/analytics/backoff_policy.rb @@ -26,25 +26,17 @@ def initialize(opts = {}) # @return [Numeric] the next backoff interval, in milliseconds. def next_interval interval = @min_timeout_ms * (@multiplier**@attempts) - interval = add_jitter(interval, @randomization_factor) - @attempts += 1 - [interval, @max_timeout_ms].min + # Clamp first, then jitter. Jittering before the clamp meant every attempt + # at the ceiling returned exactly max_timeout_ms, so a fleet that backed off + # together stayed in lockstep. Jitter only subtracts, so the ceiling holds. + capped = [interval, @max_timeout_ms].min + capped - (rand * capped * @randomization_factor) end - private - - def add_jitter(base, randomization_factor) - random_number = rand - max_deviation = base * randomization_factor - deviation = random_number * max_deviation - - if random_number < 0.5 - base - deviation - else - base + deviation - end + def reset! + @attempts = 0 end end end diff --git a/lib/segment/analytics/client.rb b/lib/segment/analytics/client.rb index 9589f69..efedc0a 100644 --- a/lib/segment/analytics/client.rb +++ b/lib/segment/analytics/client.rb @@ -32,7 +32,11 @@ def initialize(opts = {}) check_write_key! - at_exit { @worker_thread && @worker_thread[:should_exit] = true } + # The worker checks this between sleep slices, so a Retry-After or backoff + # wait is abandoned within a second rather than holding shutdown for up to + # rate_limit_retry_after_cap seconds. Assigning to a dead thread is safe; + # Thread#wakeup is not, and raising here would force a non-zero exit status. + at_exit { @worker_thread[:should_exit] = true if @worker_thread } end # Synchronously waits until the worker has flushed the queue. diff --git a/lib/segment/analytics/defaults.rb b/lib/segment/analytics/defaults.rb index aa32697..e443caf 100644 --- a/lib/segment/analytics/defaults.rb +++ b/lib/segment/analytics/defaults.rb @@ -12,6 +12,9 @@ module Request 'Content-Type' => 'application/json', 'User-Agent' => "analytics-ruby/#{Analytics::VERSION}" } RETRIES = 10 + MAX_TOTAL_BACKOFF_DURATION = 43_200 # 12 hours in seconds + MAX_RATE_LIMIT_DURATION = 43_200 # 12 hours in seconds + RATE_LIMIT_RETRY_AFTER_CAP = 300 # seconds end module Queue @@ -28,9 +31,9 @@ module MessageBatch end module BackoffPolicy - MIN_TIMEOUT_MS = 100 - MAX_TIMEOUT_MS = 10000 - MULTIPLIER = 1.5 + MIN_TIMEOUT_MS = 500 + MAX_TIMEOUT_MS = 60_000 + MULTIPLIER = 2 RANDOMIZATION_FACTOR = 0.5 end end diff --git a/lib/segment/analytics/response.rb b/lib/segment/analytics/response.rb index c31116a..0a2fd2f 100644 --- a/lib/segment/analytics/response.rb +++ b/lib/segment/analytics/response.rb @@ -12,6 +12,10 @@ def initialize(status = 200, error = nil) @status = status @error = error end + + def success? + status >= 200 && status < 300 + end end end end diff --git a/lib/segment/analytics/retry_budget.rb b/lib/segment/analytics/retry_budget.rb new file mode 100644 index 0000000..3032561 --- /dev/null +++ b/lib/segment/analytics/retry_budget.rb @@ -0,0 +1,78 @@ +# frozen_string_literal: true + +module Segment + class Analytics + # Tracks the two independent budgets one send may spend. + # + # A retryable status carrying Retry-After spends the rate-limit budget, which + # is bounded by wall clock only. Anything else retryable spends the counted + # backoff budget, bounded by both a retry count and wall clock. Keeping them + # separate is what stops a rate-limited server from exhausting the retries + # available to genuine failures. + # + # The caller performs the wait, so both methods return the delay in seconds, + # or nil when the budget is spent and the batch should be abandoned. + class RetryBudget + attr_reader :retry_count + + # Keyword arguments would be cleaner but need Ruby 2.1; the gemspec still + # declares >= 2.0, which is also what rubocop is configured to parse. + def initialize(options = {}) + @retries_remaining = options[:retries] + @backoff_policy = options[:backoff_policy] + @max_total_backoff_duration = options[:max_total_backoff_duration] + @max_rate_limit_duration = options[:max_rate_limit_duration] + @rate_limit_retry_after_cap = options[:rate_limit_retry_after_cap] + @logger = options[:logger] + @retry_count = 0 + @backoff_start_time = nil + @rate_limit_start_time = nil + end + + def next_backoff_delay + # Checked before the decrement: decrementing first spent one retry on the + # exhaustion test itself, so a configured N only ever performed N-1, and + # retries: 1 and retries: 0 were indistinguishable. + return spent('Retries exhausted for batch') if @retries_remaining <= 0 + + @retries_remaining -= 1 + + @backoff_start_time ||= monotonic_now + return spent('Max total backoff duration exceeded for batch') if elapsed?(@backoff_start_time, @max_total_backoff_duration) + + delay_ms = @backoff_policy.next_interval + @logger.debug("Retrying request, #{@retries_remaining} retries left. Waiting #{delay_ms}ms") + delay_ms.to_f / 1000 + end + + def next_rate_limit_delay(retry_after, status_code) + @rate_limit_start_time ||= monotonic_now + return spent('Max rate limit duration exceeded for batch') if elapsed?(@rate_limit_start_time, @max_rate_limit_duration) + + delay = [retry_after, @rate_limit_retry_after_cap].min + @logger.debug("Retry-After: #{delay}s on #{status_code}. Retrying after delay.") + delay + end + + def record_retry + @retry_count += 1 + end + + private + + def elapsed?(start_time, limit) + (monotonic_now - start_time) >= limit + end + + # Wall-clock time can jump; these budgets must not expire or stretch with it. + def monotonic_now + Process.clock_gettime(Process::CLOCK_MONOTONIC) + end + + def spent(message) + @logger.error(message) + nil + end + end + end +end diff --git a/lib/segment/analytics/transport.rb b/lib/segment/analytics/transport.rb index 6ee14d8..8b689dd 100644 --- a/lib/segment/analytics/transport.rb +++ b/lib/segment/analytics/transport.rb @@ -5,9 +5,11 @@ require 'segment/analytics/response' require 'segment/analytics/logging' require 'segment/analytics/backoff_policy' +require 'segment/analytics/retry_budget' require 'net/http' require 'net/https' require 'json' +require 'time' module Segment class Analytics @@ -16,22 +18,18 @@ class Transport include Segment::Analytics::Utils include Segment::Analytics::Logging + RETRYABLE_4XX = [408, 410, 429, 460].freeze + NON_RETRYABLE_5XX = [501, 505, 511].freeze + def initialize(options = {}) options[:host] ||= HOST options[:port] ||= PORT - options[:ssl] ||= SSL + options[:ssl] ||= SSL @headers = options[:headers] || HEADERS - @path = options[:path] || PATH - @retries = options[:retries] || RETRIES - @backoff_policy = - options[:backoff_policy] || Segment::Analytics::BackoffPolicy.new + @path = options[:path] || PATH - http = Net::HTTP.new(options[:host], options[:port]) - http.use_ssl = options[:ssl] - http.read_timeout = 8 - http.open_timeout = 4 - - @http = http + configure_retries(options) + @http = build_http(options) end # Sends a batch of messages to the API @@ -40,23 +38,32 @@ def initialize(options = {}) def send(write_key, batch) logger.debug("Sending request for #{batch.length} items") - last_response, exception = retry_with_backoff(@retries) do - status_code, body = send_request(write_key, batch) - error = JSON.parse(body)['error'] - should_retry = should_retry_request?(status_code, body) - logger.debug("Response status code: #{status_code}") - logger.debug("Response error: #{error}") if error + @backoff_policy.reset! if @backoff_policy.respond_to?(:reset!) + budget = new_retry_budget - [Response.new(status_code, error), should_retry] - end + loop do + begin + status_code, body, headers = send_request(write_key, batch, budget.retry_count) + rescue StandardError => e + # Connection reset, DNS failure, read timeout and friends. Retried on + # the counted backoff budget, like a retryable status code. + logger.error("Network error: #{e.message}") + return Response.new(-1, e.to_s) unless wait_to_retry(budget.next_backoff_delay, budget) - if exception - logger.error(exception.message) - exception.backtrace.each { |line| logger.error(line) } - Response.new(-1, exception.to_s) - else - last_response + next + end + + error = parse_error(body) + final = final_response(status_code, body, error) + return final if final + + delay = retry_delay(status_code, headers, budget) + return Response.new(status_code, error) unless wait_to_retry(delay, budget) end + rescue StandardError => e + logger.error(e.message) + e.backtrace.each { |line| logger.error(line) } + Response.new(-1, e.to_s) end # Closes a persistent connection if it exists @@ -66,65 +73,174 @@ def shutdown private - def should_retry_request?(status_code, body) - if status_code >= 500 - true # Server error - elsif status_code == 429 - true # Rate limited - elsif status_code >= 400 - logger.error(body) - false # Client error. Do not retry, but log + # A Response once the batch is settled, or nil while it is still retryable. + def final_response(status_code, body, error) + logger.debug("Response status code: #{status_code}") + logger.debug("Response error: #{error}") if error + + return Response.new(status_code, error) if success_status?(status_code) + return nil if retryable_status?(status_code) + + if status_code >= 300 && status_code < 400 + # Logging the body here would be useless: a redirect has none. + logger.error("Unexpected redirect (#{status_code}); batch not uploaded. " \ + 'Check whether the configured host points at a proxy or redirector.') else - false + logger.error(body) end + Response.new(status_code, error) end - # Takes a block that returns [result, should_retry]. - # - # Retries upto `retries_remaining` times, if `should_retry` is false or - # an exception is raised. `@backoff_policy` is used to determine the - # duration to sleep between attempts + # A Retry-After spends the rate-limit budget; anything else retryable + # spends the counted backoff budget. + def retry_delay(status_code, headers, budget) + retry_after = parse_retry_after(headers['retry-after']) + return budget.next_backoff_delay unless retry_after + + budget.next_rate_limit_delay(retry_after, status_code) + end + + def configure_retries(options) + @retries = options[:retries] || RETRIES + @backoff_policy = + options[:backoff_policy] || Segment::Analytics::BackoffPolicy.new + + # One policy instance serves every batch, so it has to be reset between + # them or attempt counts accumulate and each batch starts where the last + # one left off. reset! is not part of the older documented contract, which + # was next_interval alone, so a policy predating it still works — but it + # keeps that accumulation, and silently. Say so rather than letting an + # integrator find it as "retries get slower the longer we run". + unless @backoff_policy.respond_to?(:reset!) + logger.warn( + 'backoff_policy does not implement reset!; attempt counts will ' \ + 'accumulate across batches. Add a reset! method that clears them.' + ) + end + @max_total_backoff_duration = options[:max_total_backoff_duration] || + MAX_TOTAL_BACKOFF_DURATION + @max_rate_limit_duration = options[:max_rate_limit_duration] || + MAX_RATE_LIMIT_DURATION + @rate_limit_retry_after_cap = options[:rate_limit_retry_after_cap] || + RATE_LIMIT_RETRY_AFTER_CAP + end + + def build_http(options) + http = Net::HTTP.new(options[:host], options[:port]) + http.use_ssl = options[:ssl] + http.read_timeout = 8 + http.open_timeout = 4 + http + end + + # How long a sliced retry wait sleeps before re-checking for shutdown. + SHUTDOWN_CHECK_INTERVAL = 1 + + def new_retry_budget + RetryBudget.new( + :retries => @retries, + :backoff_policy => @backoff_policy, + :max_total_backoff_duration => @max_total_backoff_duration, + :max_rate_limit_duration => @max_rate_limit_duration, + :rate_limit_retry_after_cap => @rate_limit_retry_after_cap, + :logger => logger + ) + end + + # nil delay means the budget is spent. Sleeping here rather than inside + # RetryBudget keeps the wait on Transport, where callers stub it. + def wait_to_retry(delay, budget) + return false if delay.nil? + return false unless interruptible_sleep(delay) + + budget.record_retry + true + end + + # Sleeps in slices so shutdown is noticed within SHUTDOWN_CHECK_INTERVAL + # rather than after the whole delay, which can be rate_limit_retry_after_cap + # seconds. Returns false if shutdown was requested. # - # Returns [last_result, raised_exception] - def retry_with_backoff(retries_remaining, &block) - result, caught_exception = nil - should_retry = false + # Thread#wakeup is deliberately not used for this: it only cuts short a sleep + # already in progress, so a wakeup arriving while the worker is mid-request is + # lost and the next sleep still runs in full. + def interruptible_sleep(seconds) + remaining = seconds + while remaining > 0 + return false if Thread.current[:should_exit] - begin - result, should_retry = yield - return [result, nil] unless should_retry - rescue StandardError => e - should_retry = true - caught_exception = e + slice = [remaining, SHUTDOWN_CHECK_INTERVAL].min + sleep(slice) + remaining -= slice end + !Thread.current[:should_exit] + end - if should_retry && (retries_remaining > 1) - logger.debug("Retrying request, #{retries_remaining} retries left") - sleep(@backoff_policy.next_interval.to_f / 1000) - retry_with_backoff(retries_remaining - 1, &block) + def parse_error(body) + JSON.parse(body)['error'] + rescue StandardError + nil + end + + # Only 2xx. Net::HTTP does not follow redirects, so a 3xx means nothing was + # uploaded; calling it success would drop the batch silently. + def success_status?(code) + code >= 200 && code < 300 + end + + def retryable_status?(code) + if code >= 500 && code < 600 + !NON_RETRYABLE_5XX.include?(code) else - [result, caught_exception] + RETRYABLE_4XX.include?(code) + end + end + + def parse_retry_after(value) + return nil if value.nil? + + str = value.is_a?(Array) ? value.first : value + return nil if str.nil? + + str = str.strip + + # Try integer seconds + if str =~ /\A\d+\z/ + seconds = str.to_i + return seconds > 0 ? seconds : nil + end + + # Try HTTP-date (RFC 7231 S7.1.1.1) + begin + target = Time.httpdate(str) + seconds = (target - Time.now).to_i + seconds > 0 ? seconds : nil + rescue ArgumentError + nil end end - # Sends a request for the batch, returns [status_code, body] - def send_request(write_key, batch) + # Sends a request for the batch, returns [status_code, body, headers] + def send_request(write_key, batch, retry_count = 0) payload = JSON.generate( :sentAt => datetime_in_iso8601(Time.now), :batch => batch ) - request = Net::HTTP::Post.new(@path, @headers) + headers = @headers.dup + headers['X-Retry-Count'] = retry_count.to_s if retry_count > 0 + + request = Net::HTTP::Post.new(@path, headers) request.basic_auth(write_key, nil) if self.class.stub logger.debug "stubbed request to #{@path}: " \ "write key = #{write_key}, batch = #{JSON.generate(batch)}" - [200, '{}'] + [200, '{}', {}] else - @http.start unless @http.started? # Maintain a persistent connection + @http.start unless @http.started? response = @http.request(request, payload) - [response.code.to_i, response.body] + [response.code.to_i, response.body, response.to_hash] end end diff --git a/lib/segment/analytics/worker.rb b/lib/segment/analytics/worker.rb index 6a7d68e..c4bf728 100644 --- a/lib/segment/analytics/worker.rb +++ b/lib/segment/analytics/worker.rb @@ -45,7 +45,7 @@ def run end res = @transport.send @write_key, @batch - @on_error.call(res.status, res.error) unless res.status == 200 + @on_error.call(res.status, res.error) unless res.success? @lock.synchronize { @batch.clear } end diff --git a/spec/segment/analytics/backoff_policy_spec.rb b/spec/segment/analytics/backoff_policy_spec.rb index 25ef05e..6156bb7 100644 --- a/spec/segment/analytics/backoff_policy_spec.rb +++ b/spec/segment/analytics/backoff_policy_spec.rb @@ -67,6 +67,28 @@ class Analytics end end + describe '#reset!' do + it 'resets attempts to 0' do + subject.next_interval + subject.next_interval + subject.next_interval + subject.reset! + expect(subject.instance_variable_get(:@attempts)).to eq(0) + end + + it 'causes next_interval to restart from minimum' do + subject_with_params = described_class.new( + min_timeout_ms: 1000, + max_timeout_ms: 10000, + multiplier: 2, + randomization_factor: 0.5 + ) + 3.times { subject_with_params.next_interval } + subject_with_params.reset! + expect(subject_with_params.next_interval).to be_within(500).of(1000) + end + end + describe '#next_interval' do subject { described_class.new( @@ -84,9 +106,18 @@ class Analytics expect(subject.next_interval).to be_within(4000).of(8000) end - it 'caps maximum duration at max_timeout_secs' do + it 'never exceeds max_timeout_ms once the ceiling is reached' do + 10.times { subject.next_interval } + 20.times do + expect(subject.next_interval).to be <= 10000 + end + end + + it 'jitters at the ceiling instead of returning a fixed value' do 10.times { subject.next_interval } - expect(subject.next_interval).to eq(10000) + intervals = Array.new(20) { subject.next_interval } + expect(intervals.uniq.size).to be > 1 + expect(intervals.min).to be >= 5000 end end end diff --git a/spec/segment/analytics/response_spec.rb b/spec/segment/analytics/response_spec.rb index bb673db..147698d 100644 --- a/spec/segment/analytics/response_spec.rb +++ b/spec/segment/analytics/response_spec.rb @@ -13,6 +13,20 @@ class Analytics it { expect(subject).to respond_to(:error) } end + describe '#success?' do + it { expect(described_class.new(200, nil).success?).to be true } + it { expect(described_class.new(201, nil).success?).to be true } + it { expect(described_class.new(204, nil).success?).to be true } + it { expect(described_class.new(300, nil).success?).to be false } + it { expect(described_class.new(301, nil).success?).to be false } + it { expect(described_class.new(302, nil).success?).to be false } + it { expect(described_class.new(304, nil).success?).to be false } + it { expect(described_class.new(400, nil).success?).to be false } + it { expect(described_class.new(429, nil).success?).to be false } + it { expect(described_class.new(500, nil).success?).to be false } + it { expect(described_class.new(-1, nil).success?).to be false } + end + describe '#initialize' do let(:status) { 404 } let(:error) { 'Oh No' } diff --git a/spec/segment/analytics/retry_budget_spec.rb b/spec/segment/analytics/retry_budget_spec.rb new file mode 100644 index 0000000..6350f60 --- /dev/null +++ b/spec/segment/analytics/retry_budget_spec.rb @@ -0,0 +1,49 @@ +# frozen_string_literal: true + +require 'spec_helper' + +module Segment + class Analytics + describe RetryBudget do + let(:logger) { Logger.new(File::NULL) } + + def budget(retries, intervals = nil) + described_class.new( + :retries => retries, + :backoff_policy => FakeBackoffPolicy.new(intervals || Array.new(retries, 1000)), + :max_total_backoff_duration => 43_200, + :max_rate_limit_duration => 43_200, + :rate_limit_retry_after_cap => 300, + :logger => logger + ) + end + + describe '#next_backoff_delay' do + it 'grants exactly as many retries as configured' do + # The count used to be decremented before the exhaustion check, so a + # configured N yielded N-1. go, python and java all grant N. + subject = budget(3) + + expect(subject.next_backoff_delay).to eq(1.0) + expect(subject.next_backoff_delay).to eq(1.0) + expect(subject.next_backoff_delay).to eq(1.0) + expect(subject.next_backoff_delay).to be_nil + end + + it 'grants one retry for retries: 1' do + subject = budget(1) + + expect(subject.next_backoff_delay).to eq(1.0) + expect(subject.next_backoff_delay).to be_nil + end + + it 'grants no retries for retries: 0' do + # retries: 0 and retries: 1 were previously indistinguishable. + subject = budget(0, [1000]) + + expect(subject.next_backoff_delay).to be_nil + end + end + end + end +end diff --git a/spec/segment/analytics/transport_spec.rb b/spec/segment/analytics/transport_spec.rb index 488b3ee..3e2580f 100644 --- a/spec/segment/analytics/transport_spec.rb +++ b/spec/segment/analytics/transport_spec.rb @@ -115,6 +115,7 @@ class Analytics allow(http).to receive(:start) allow(http).to receive(:request) { response } allow(response).to receive(:body) { response_body } + allow(response).to receive(:to_hash) { {} } end it 'initalizes a new Net::HTTP::Post with path and default headers' do @@ -162,7 +163,7 @@ class Analytics let(:status_code) { status_code } let(:body) { body } let(:retries) { 4 } - let(:backoff_policy) { FakeBackoffPolicy.new([1000, 1000, 1000]) } + let(:backoff_policy) { FakeBackoffPolicy.new([1000, 1000, 1000, 1000]) } subject { described_class.new(retries: retries, backoff_policy: backoff_policy) @@ -170,10 +171,10 @@ class Analytics it 'retries the request' do expect(subject) - .to receive(:sleep) - .exactly(retries - 1).times + .to receive(:interruptible_sleep) + .exactly(retries).times .with(1) - .and_return(nil) + .and_return(true) subject.send(write_key, batch) end end @@ -187,7 +188,7 @@ class Analytics it 'does not retry the request' do expect(subject) - .to receive(:sleep) + .to receive(:interruptible_sleep) .never subject.send(write_key, batch) end @@ -204,6 +205,16 @@ class Analytics end end + context '3xx is not retried and is not success' do + let(:status_code) { 301 } + it 'returns the status without retrying, and does not report success' do + expect(subject).not_to receive(:interruptible_sleep) + response = subject.send(write_key, batch) + expect(response.status).to eq(301) + expect(response.success?).to be false + end + end + context 'request results in errorful response' do let(:error) { 'this is an error' } let(:response_body) { { error: error }.to_json } @@ -218,28 +229,309 @@ class Analytics it_behaves_like('retried request', 500, '{}') it_behaves_like('retried request', 503, '{}') - # All 4xx errors other than 429 (rate limited) must be retried + # 429 is retried it_behaves_like('retried request', 429, '{}') it_behaves_like('non-retried request', 404, '{}') it_behaves_like('non-retried request', 400, '{}') + + # Non-retryable 5xx: 501, 505, 511 + it_behaves_like('non-retried request', 501, '{}') + it_behaves_like('non-retried request', 505, '{}') + it_behaves_like('non-retried request', 511, '{}') + + # Retryable 4xx: 408, 410, 460 + it_behaves_like('retried request', 408, '{}') + it_behaves_like('retried request', 410, '{}') + it_behaves_like('retried request', 460, '{}') + end + + context '429 with Retry-After header' do + let(:status_code) { 429 } + let(:retry_after_seconds) { 2 } + subject { described_class.new(retries: 4, backoff_policy: FakeBackoffPolicy.new([1000, 1000, 1000])) } + + before do + allow(response).to receive(:to_hash) { { 'retry-after' => [retry_after_seconds.to_s] } } + # Second attempt succeeds + success_response = Net::HTTPResponse.new(1.1, 200, '{}') + allow(success_response).to receive(:body) { '{}' } + allow(success_response).to receive(:to_hash) { {} } + http = subject.instance_variable_get(:@http) + allow(http).to receive(:request).and_return(response, success_response) + end + + it 'sleeps for the Retry-After duration' do + expect(subject).to receive(:interruptible_sleep).with(2).once.and_return(true) + subject.send(write_key, batch) + end + + it 'caps Retry-After at RATE_LIMIT_RETRY_AFTER_CAP' do + allow(response).to receive(:to_hash) { { 'retry-after' => ['9999'] } } + expect(subject).to receive(:interruptible_sleep).with(described_class::RATE_LIMIT_RETRY_AFTER_CAP).once.and_return(true) + subject.send(write_key, batch) + end + + it 'returns success after retry' do + allow(subject).to receive(:interruptible_sleep).and_return(true) + expect(subject.send(write_key, batch).success?).to be true + end + end + + context '503 with Retry-After header' do + let(:status_code) { 503 } + subject { described_class.new(retries: 4, backoff_policy: FakeBackoffPolicy.new([1000, 1000, 1000])) } + + before do + allow(response).to receive(:to_hash) { { 'retry-after' => ['2'] } } + success_response = Net::HTTPResponse.new(1.1, 200, '{}') + allow(success_response).to receive(:body) { '{}' } + allow(success_response).to receive(:to_hash) { {} } + http = subject.instance_variable_get(:@http) + allow(http).to receive(:request).and_return(response, success_response) + end + + it 'sleeps for the Retry-After duration' do + expect(subject).to receive(:interruptible_sleep).with(2).once.and_return(true) + subject.send(write_key, batch) + end + + it 'does not decrement retries_remaining (uses rate-limit path)' do + allow(subject).to receive(:interruptible_sleep).and_return(true) + # With retries: 1, a 503+Retry-After should NOT exhaust retries because + # it uses the rate-limit path (no retry budget cost) + transport = described_class.new(retries: 1, backoff_policy: FakeBackoffPolicy.new([1000])) + http = transport.instance_variable_get(:@http) + allow(http).to receive(:start) + success_response = Net::HTTPResponse.new(1.1, 200, '{}') + allow(success_response).to receive(:body) { '{}' } + allow(success_response).to receive(:to_hash) { {} } + allow(http).to receive(:request).and_return(response, success_response) + allow(transport).to receive(:interruptible_sleep).and_return(true) + result = transport.send(write_key, batch) + expect(result.status).to eq(200) + end + end + + context '529 with Retry-After header' do + let(:status_code) { 529 } + subject { described_class.new(retries: 4, backoff_policy: FakeBackoffPolicy.new([1000, 1000, 1000])) } + + before do + allow(response).to receive(:to_hash) { { 'retry-after' => ['1'] } } + success_response = Net::HTTPResponse.new(1.1, 200, '{}') + allow(success_response).to receive(:body) { '{}' } + allow(success_response).to receive(:to_hash) { {} } + http = subject.instance_variable_get(:@http) + allow(http).to receive(:request).and_return(response, success_response) + end + + it 'sleeps for the Retry-After duration' do + expect(subject).to receive(:interruptible_sleep).with(1).once.and_return(true) + subject.send(write_key, batch) + end + + it 'returns success after retry' do + allow(subject).to receive(:interruptible_sleep).and_return(true) + expect(subject.send(write_key, batch).success?).to be true + end + + it 'does not decrement retries_remaining (uses rate-limit path)' do + # With retries: 1, a 529+Retry-After should NOT exhaust retries + transport = described_class.new(retries: 1, backoff_policy: FakeBackoffPolicy.new([1000])) + http = transport.instance_variable_get(:@http) + allow(http).to receive(:start) + success_response = Net::HTTPResponse.new(1.1, 200, '{}') + allow(success_response).to receive(:body) { '{}' } + allow(success_response).to receive(:to_hash) { {} } + allow(http).to receive(:request).and_return(response, success_response) + allow(transport).to receive(:interruptible_sleep).and_return(true) + result = transport.send(write_key, batch) + expect(result.status).to eq(200) + end + end + + context 'X-Retry-Count header' do + let(:status_code) { 500 } + let(:backoff_policy) { FakeBackoffPolicy.new([1, 1, 1]) } + subject { described_class.new(retries: 3, backoff_policy: backoff_policy) } + + it 'does not send X-Retry-Count on first attempt' do + allow(subject).to receive(:interruptible_sleep).and_return(true) + first_request = nil + http = subject.instance_variable_get(:@http) + allow(http).to receive(:request) do |req, _| + first_request ||= req + response + end + subject.send(write_key, batch) + expect(first_request['X-Retry-Count']).to be_nil + end + + it 'sends X-Retry-Count incrementing on retries' do + allow(subject).to receive(:interruptible_sleep).and_return(true) + requests = [] + http = subject.instance_variable_get(:@http) + allow(http).to receive(:request) do |req, _| + requests << req + response + end + subject.send(write_key, batch) + expect(requests[1]['X-Retry-Count']).to eq('1') + expect(requests[2]['X-Retry-Count']).to eq('2') + expect(requests[3]['X-Retry-Count']).to eq('3') + end + end + + context 'transient network error' do + it 'retries the request instead of dropping the batch' do + success_response = Net::HTTPResponse.new(1.1, 200, '{}') + allow(success_response).to receive(:body) { '{}' } + allow(success_response).to receive(:to_hash) { {} } + + http = subject.instance_variable_get(:@http) + calls = 0 + allow(http).to receive(:request) do + calls += 1 + raise Errno::ECONNRESET, 'reset' if calls == 1 + + success_response + end + allow(subject).to receive(:interruptible_sleep).and_return(true) + + response = subject.send(write_key, batch) + + expect(calls).to eq(2) + expect(response.status).to eq(200) + end + + it 'gives up once the retry budget is spent' do + http = subject.instance_variable_get(:@http) + allow(http).to receive(:request).and_raise(Errno::ECONNRESET, 'reset') + allow(subject).to receive(:interruptible_sleep).and_return(true) + + response = subject.send(write_key, batch) + + expect(response.status).to eq(-1) + expect(response.error).to match(/reset/) + end + end + + context 'private helpers' do + describe '#success_status?' do + it { expect(subject.__send__(:success_status?, 200)).to be true } + it { expect(subject.__send__(:success_status?, 201)).to be true } + # Only 2xx: Net::HTTP does not follow redirects, so a 3xx means + # nothing was uploaded. + it { expect(subject.__send__(:success_status?, 301)).to be false } + it { expect(subject.__send__(:success_status?, 304)).to be false } + it { expect(subject.__send__(:success_status?, 400)).to be false } + it { expect(subject.__send__(:success_status?, 500)).to be false } + end + + describe '#retryable_status?' do + it { expect(subject.__send__(:retryable_status?, 500)).to be true } + it { expect(subject.__send__(:retryable_status?, 503)).to be true } + it { expect(subject.__send__(:retryable_status?, 429)).to be true } + it { expect(subject.__send__(:retryable_status?, 408)).to be true } + it { expect(subject.__send__(:retryable_status?, 410)).to be true } + it { expect(subject.__send__(:retryable_status?, 460)).to be true } + it { expect(subject.__send__(:retryable_status?, 400)).to be false } + it { expect(subject.__send__(:retryable_status?, 404)).to be false } + it { expect(subject.__send__(:retryable_status?, 501)).to be false } + it { expect(subject.__send__(:retryable_status?, 505)).to be false } + it { expect(subject.__send__(:retryable_status?, 511)).to be false } + end + + describe '#parse_retry_after' do + it { expect(subject.__send__(:parse_retry_after, '60')).to eq(60) } + it { expect(subject.__send__(:parse_retry_after, ['60'])).to eq(60) } + it { expect(subject.__send__(:parse_retry_after, '0')).to be_nil } + it { expect(subject.__send__(:parse_retry_after, '-1')).to be_nil } + it { expect(subject.__send__(:parse_retry_after, nil)).to be_nil } + it { expect(subject.__send__(:parse_retry_after, '')).to be_nil } + it { expect(subject.__send__(:parse_retry_after, 'garbage')).to be_nil } + + it 'parses HTTP-date 2 seconds in the future' do + future = (Time.now + 2).httpdate + result = subject.__send__(:parse_retry_after, future) + expect(result).to be_between(1, 3) + end + + it 'returns nil for HTTP-date in the past' do + past = (Time.now - 10).httpdate + result = subject.__send__(:parse_retry_after, past) + expect(result).to be_nil + end + end end - context 'request or parsing of response results in an exception' do + context 'response body is malformed JSON but status is 200' do let(:response_body) { 'Malformed JSON ---' } subject { described_class.new(retries: 0) } - it 'returns a -1 for status' do - expect(subject.send(write_key, batch).status).to eq(-1) + it 'treats 200 as success regardless of body' do + expect(subject.send(write_key, batch).status).to eq(200) end - it 'has a connection error' do + it 'has nil error when body is unparseable' do error = subject.send(write_key, batch).error - expect(error).not_to be_nil + expect(error).to be_nil end + end + end + end + + describe 'a backoff_policy without reset!' do + # One policy instance serves every batch, so a policy predating reset! + # keeps accumulating attempts and gets slower the longer a process runs. + let(:legacy_policy) do + Class.new do + def next_interval + 1 + end + end.new + end + + it 'warns that attempt counts will accumulate across batches' do + expect(legacy_policy).not_to respond_to(:reset!) + expect(Segment::Analytics::Logging.logger).to receive(:warn).with(/reset!/) + + described_class.new(:backoff_policy => legacy_policy) + end + + it 'stays quiet for a policy that implements it' do + expect(Segment::Analytics::Logging.logger).not_to receive(:warn) - it_behaves_like('retried request', 200, 'Malformed JSON ---') + described_class.new(:backoff_policy => Segment::Analytics::BackoffPolicy.new) + end + end + + describe '#interruptible_sleep' do + subject { described_class.new } + + it 'abandons the wait when shutdown is requested instead of sleeping it out' do + # The wait used to be a single sleep broken by Thread#wakeup, which only + # interrupts a sleep already in progress and raises ThreadError if the + # thread has finished. Slicing removes the need for it. + elapsed = nil + + worker = Thread.new do + started = Process.clock_gettime(Process::CLOCK_MONOTONIC) + result = subject.__send__(:interruptible_sleep, 30) + elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started + result end + + sleep 0.1 + worker[:should_exit] = true + + expect(worker.value).to be false + expect(elapsed).to be < 5 + end + + it 'reports completion when the delay elapses' do + expect(Thread.new { subject.__send__(:interruptible_sleep, 0) }.value).to be true end end end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 8dc8634..8b255e2 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -114,6 +114,8 @@ def next_interval raise 'FakeBackoffPolicy has no values left' if @interval_values.empty? @interval_values.shift end + + def reset!; end end # usage: