diff --git a/CHANGELOG.md b/CHANGELOG.md index c6b25b3f..73fe3d8a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,7 +6,12 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [unreleased] -- See diff: https://github.com/barkibu/kb-ruby/compare/v1.2.0...HEAD +- See diff: https://github.com/barkibu/kb-ruby/compare/v1.3.0...HEAD + +## [1.3.0] +- Retry transport failures once (`faraday-retry`, already in the Faraday 1.10 bundle, now an explicit dependency). `KB::RetryPolicy` decides by the underlying error, not the Faraday class: failures where the request never left (`Net::OpenTimeout`, `ECONNREFUSED`, `EHOSTUNREACH`, `ENETUNREACH`, `EADDRNOTAVAIL`, `SocketError`) retry for every verb; any other transport failure (read/write timeout, reset, EOF, TLS) retries for GET/HEAD only (and not when the call raised its own `read_timeout:`, so a 30s read isn't doubled); HTTP error responses never retry. New settings `KB.config.request.retries` (default 1, 0 disables) and `retry_interval` (default 0.1s, randomized up to 2x). Worst-case latency is now two attempts' worth of phase budgets. +- `request.kb_client` payload gains `retries` and `retry_errors` on retried calls; the Datadog subscriber tags them as `kb.retries` / `kb.retry_errors`. The event and span cover all attempts, so a call that succeeded on retry is not an error. +- `KB::Listable.all` (and so `PetParent.all`, `Pet.all`, `Breed.all`, `Product.all`, `Plan.all`, `Assessment.all`) now wraps `Faraday::ConnectionFailed` in `KB::Error` like every other model call, instead of re-raising it raw. Code rescuing `Faraday::ConnectionFailed` around `.all` must rescue `KB::Error` instead; none of Funnel, Global Admin or connected_health does. ## [1.2.0] - `KB::Client` emits one `request.kb_client` `ActiveSupport::Notifications` event per KB call (`KB::Client::REQUEST_EVENT`), wrapping cache lookup, connect, TLS, write, read and parsing. Payload: `verb`, `path`, `base_url`, `cache_hit` (GET only), `status`, plus ActiveSupport's `exception`/`exception_object` when the call raised. Every public method now goes through one private `perform` seam; no behaviour change (same cache keys, params and error classes). diff --git a/Gemfile.lock b/Gemfile.lock index ee2bb254..8cfa0117 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,17 +1,18 @@ PATH remote: . specs: - barkibu-kb (1.2.0) + barkibu-kb (1.3.0) activemodel (>= 4.0.2) activerecord activesupport (>= 3.0.0) dry-configurable (~> 0.9) faraday faraday-net_http (~> 1.0) + faraday-retry (~> 1.0) faraday_middleware i18n - barkibu-kb-fake (1.2.0) - barkibu-kb (= 1.2.0) + barkibu-kb-fake (1.3.0) + barkibu-kb (= 1.3.0) countries sinatra webmock diff --git a/README.md b/README.md index 52777192..f3654472 100644 --- a/README.md +++ b/README.md @@ -74,14 +74,49 @@ and write budgets stay global: KB::Pet.kb_client.request('birthdays', filters: { month: 9, day: 22, size: 1000 }, read_timeout: 30) ``` +#### Retries + +The client retries a failed call once when the failure is in the transport, never +when KB answered with an HTTP error. Which calls retry depends on whether the +request can have reached KB (`KB::RetryPolicy`): + +| Failure | Retried for | +|---|---| +| Never sent: connect/TLS timeout (`Net::OpenTimeout`), connection refused, host/network unreachable, DNS failure | every verb, POST included | +| Maybe sent: read/write timeout, connection reset, EOF, TLS error mid-stream | GET and HEAD only | +| HTTP 4xx/5xx | never | + +PUT and DELETE are not retried on "maybe sent" failures: `upsert` and +`PetParent#merge!` are PUTs whose second run is not a no-op on KB's side, and a +repeated DELETE would turn a success into a 404. A call that raised its own read +budget (`read_timeout:` on `KB::Client#request`) is not retried on "maybe sent" +failures either, so a 30s birthdays read can't become 60s; failures that never +reached KB are still retried. + +```ruby +# config/initializers/kb_ruby.rb +KB.config.request.retries = 1 # default; 0 disables retries +KB.config.request.retry_interval = 0.1 # default, seconds; each wait is 1x-2x this +``` + +Like the timeouts, these are read when a client builds its connection, i.e. on +its first call, so set them in an initializer. + +Worst case, a call now takes two attempts' worth of phase budgets plus the +interval, e.g. a GET that read-times-out twice takes about 2 x (1 + 3 + 5)s with +the default timeouts. + #### Instrumentation Every KB call emits one `request.kb_client` event through `ActiveSupport::Notifications`, wrapping the whole call: cache lookup, TCP connect, TLS, write, read and JSON parsing. The payload carries `verb`, `path`, -`base_url`, `cache_hit` (GET calls only), `status` (when a response arrived) and -ActiveSupport's `exception` / `exception_object` when the call raised. Subscribe -to it for logging, metrics or anything else: +`base_url`, `cache_hit` (GET calls only), `status` (when a response arrived), +`retries` and `retry_errors` (only when the call was retried: the count, and the +underlying error class of each failed attempt, e.g. `["Net::OpenTimeout"]`) and +ActiveSupport's `exception` / `exception_object` when the call raised. The event +covers the whole call including retries, so `exception` is set only when every +attempt failed. Subscribe to it for logging, metrics or anything else: ```ruby ActiveSupport::Notifications.subscribe(KB::Client::REQUEST_EVENT) do |event| @@ -110,8 +145,10 @@ tracer's own Net::HTTP spans nest under it. It inherits the app's service knowledge-base service either: it measures the client's whole call, not a KB operation. Resources are low-cardinality (`GET /v1/pets/birthdays`, `GET /v1/pets/?/contracts`). Tags: `peer.hostname` (the KB host used), -`kb.method`, `kb.cache_hit` (GET calls only), `http.status_code`, plus the -standard `error.type`/`error.message` when the call raises. +`kb.method`, `kb.cache_hit` (GET calls only), `http.status_code`, `kb.retries` +and `kb.retry_errors` (retried calls only), plus the standard +`error.type`/`error.message` when the call raises. A span with `kb.retries` and +no error is a failure the retry absorbed. Why not rely on the Net::HTTP tracer alone: faraday-net_http opens the socket before `Net::HTTP#request`, the method that tracer patches, so a connect timeout diff --git a/barkibu-kb.gemspec b/barkibu-kb.gemspec index 731ca976..99d2c65f 100644 --- a/barkibu-kb.gemspec +++ b/barkibu-kb.gemspec @@ -54,5 +54,6 @@ Gem::Specification.new do |spec| spec.add_runtime_dependency 'faraday' spec.add_runtime_dependency 'faraday-net_http', '~> 1.0' spec.add_runtime_dependency 'faraday_middleware' + spec.add_runtime_dependency 'faraday-retry', '~> 1.0' spec.add_runtime_dependency 'i18n' end diff --git a/lib/barkibu-kb.rb b/lib/barkibu-kb.rb index c2ec5a4b..c91e06a1 100644 --- a/lib/barkibu-kb.rb +++ b/lib/barkibu-kb.rb @@ -21,6 +21,9 @@ module KB setting :connect_timeout, default: 1 setting :write_timeout, default: 3 setting :read_timeout, default: 5 + # Retries after a transport failure, per KB::RetryPolicy. 0 disables retries. + setting :retries, default: 1 + setting :retry_interval, default: 0.1 end end @@ -29,6 +32,7 @@ module KB require 'kb/cache' require 'kb/client_resolver' require 'kb/errors' +require 'kb/retry_policy' require 'kb/client' require 'kb/concerns' diff --git a/lib/kb/client.rb b/lib/kb/client.rb index f71b372c..048b0699 100644 --- a/lib/kb/client.rb +++ b/lib/kb/client.rb @@ -2,6 +2,7 @@ module KB class Client # Emitted once per KB call, wrapping cache lookup and the HTTP request. # Payload: verb, path, base_url, cache_hit (GET only), status (when a response arrived), + # retries / retry_errors (only when the call was retried, see KB::RetryPolicy), # plus ActiveSupport's exception/exception_object when the call raised. REQUEST_EVENT = 'request.kb_client'.freeze @@ -74,7 +75,10 @@ def perform(verb, path, payload = nil, cache_key: nil, read_timeout: nil) end def http(event, payload, read_timeout) - response = connection.public_send(event[:verb], event[:path], payload, &request_options(read_timeout)) + response = connection.public_send(event[:verb], event[:path], payload) do |req| + req.options.read_timeout = read_timeout if read_timeout + RetryPolicy.track(req, event, read_timeout) + end event[:status] = response.status response.body rescue Faraday::ClientError, Faraday::ServerError => e @@ -101,6 +105,7 @@ def attributes_to_json(attributes) def connection @connection ||= Faraday.new(url: base_url, headers: headers, request: request_timeouts) do |conn| + conn.request :retry, RetryPolicy.middleware_options conn.response :json conn.response :raise_error if KB.config.log_level == :debugger @@ -112,12 +117,6 @@ def connection end end - def request_options(read_timeout) - return nil if read_timeout.nil? - - ->(req) { req.options.read_timeout = read_timeout } - end - def request_timeouts { open_timeout: KB.config.request.connect_timeout, diff --git a/lib/kb/instrumentation/datadog.rb b/lib/kb/instrumentation/datadog.rb index 70d71e7c..f6e319a2 100644 --- a/lib/kb/instrumentation/datadog.rb +++ b/lib/kb/instrumentation/datadog.rb @@ -72,9 +72,21 @@ def finish(_name, _id, payload) span.set_tag('kb.cache_hit', payload[:cache_hit].to_s) if payload.key?(:cache_hit) span.set_tag('http.status_code', payload[:status].to_s) if payload[:status] + tag_retries(span, payload) span.set_error(payload[:exception_object]) if payload[:exception_object] span.finish end + + private + + # Only on retried calls: `kb.retries` (numeric) and the distinct underlying + # errors that triggered them, e.g. `Net::OpenTimeout`. + def tag_retries(span, payload) + return unless payload[:retries] + + span.set_tag('kb.retries', payload[:retries]) + span.set_tag('kb.retry_errors', payload[:retry_errors].uniq.join(',')) + end end end end diff --git a/lib/kb/models/concerns/listable.rb b/lib/kb/models/concerns/listable.rb index 19e5b4c1..66162560 100644 --- a/lib/kb/models/concerns/listable.rb +++ b/lib/kb/models/concerns/listable.rb @@ -11,8 +11,6 @@ def all(filters = {}) kb_client.all(filters).map do |pet_parent| from_api pet_parent end - rescue Faraday::ConnectionFailed => e - raise e rescue Faraday::Error => e raise KB::Error.from_faraday(e) end diff --git a/lib/kb/retry_policy.rb b/lib/kb/retry_policy.rb new file mode 100644 index 00000000..1d51c4de --- /dev/null +++ b/lib/kb/retry_policy.rb @@ -0,0 +1,88 @@ +require 'socket' +require 'net/http' +require 'faraday/retry' + +module KB + # Decides which failed KB calls the client retries. + # + # Two classes of transport failure, told apart by the underlying Ruby error + # rather than the Faraday class (adapters disagree on the Faraday class: the + # net_http adapter wraps Net::OpenTimeout as ConnectionFailed, the persistent + # one as TimeoutError): + # + # - never sent: TCP connect / TLS handshake did not complete, so KB cannot have + # seen the request. Safe to retry for every verb, POST included. + # - maybe sent: anything else the transport raises (read/write timeout, reset, + # EOF, TLS error mid-stream). KB may have processed it, so only GET/HEAD are + # retried. PUT/DELETE are left out on purpose: `upsert` and `merge!` are PUTs + # whose second run is not a no-op on KB's side, and a repeated DELETE would + # turn a success into a 404. + # A call that raised its own read budget (`read_timeout:`, e.g. 30s for + # birthdays) is not retried on these either, so its worst case isn't doubled. + # + # HTTP responses (4xx/5xx) are never retried: KB answered. + module RetryPolicy + NOT_SENT_ERRORS = [ + Net::OpenTimeout, + Errno::ECONNREFUSED, + Errno::EHOSTUNREACH, + Errno::ENETUNREACH, + Errno::EADDRNOTAVAIL, + SocketError # DNS resolution + ].freeze + TRANSPORT_ERRORS = [Faraday::ConnectionFailed, Faraday::TimeoutError, Faraday::SSLError].freeze + MAYBE_SENT_VERBS = %i[get head].freeze + + module_function + + def retry?(verb, error, own_read_budget: false) + return false unless TRANSPORT_ERRORS.any? { |klass| error.is_a?(klass) } + + not_sent?(error) || (MAYBE_SENT_VERBS.include?(verb) && !own_read_budget) + end + + def not_sent?(error) + cause = root_cause(error) + NOT_SENT_ERRORS.any? { |klass| cause.is_a?(klass) } + end + + # The Ruby error behind a Faraday error. `wrapped_exception` is Faraday's own + # explicit link to it (Ruby's `cause` is only whatever was being rescued at + # the raise, usually the same object). Faraday's adapters wrap the Ruby error + # one level deep, so one level is enough. + def root_cause(error) + (error.respond_to?(:wrapped_exception) && error.wrapped_exception) || error.cause || error + end + + # Options for faraday-retry's middleware, read from KB.config.request. + def middleware_options + { + max: KB.config.request.retries, + interval: KB.config.request.retry_interval, + interval_randomness: 1, # 1x-2x the interval, so a burst of callers doesn't retry in lockstep + exceptions: TRANSPORT_ERRORS, + methods: [], # always ask retry_if + retry_if: lambda do |env, error| + retry?(env[:method], error, own_read_budget: env[:request].context&.dig(:kb_own_read_budget)) + end, + retry_block: ->(env, _options, _retries_left, error) { record(env, error) } + } + end + + # Hands the request.kb_client event payload (and whether the call set its own + # read budget) to the middleware through the request context, so each retry + # is reported on the call's own event. + def track(request, event, read_timeout = nil) + tracking = { kb_event: event, kb_own_read_budget: !read_timeout.nil? } + request.options.context = (request.options.context || {}).merge(tracking) + end + + def record(env, error) + event = env[:request].context&.dig(:kb_event) + return unless event + + event[:retries] = event.fetch(:retries, 0) + 1 + (event[:retry_errors] ||= []) << root_cause(error).class.name + end + end +end diff --git a/lib/kb/version.rb b/lib/kb/version.rb index 41ad82d5..c49d8adb 100644 --- a/lib/kb/version.rb +++ b/lib/kb/version.rb @@ -1,3 +1,3 @@ module KB - VERSION = '1.2.0'.freeze + VERSION = '1.3.0'.freeze end diff --git a/spec/client_retries_spec.rb b/spec/client_retries_spec.rb new file mode 100644 index 00000000..c7e03798 --- /dev/null +++ b/spec/client_retries_spec.rb @@ -0,0 +1,93 @@ +require 'spec_helper' + +RSpec.describe KB::Client, '#request retries' do + subject(:client) { described_class.new('http://kb.test/v1/pets', api_key: 'test') } + + let(:json) { { status: 200, body: '{"key":"k"}', headers: { 'Content-Type' => 'application/json' } } } + let(:events) { [] } + + around do |example| + KB.config.request.retry_interval = 0 + subscriber = ActiveSupport::Notifications.subscribe(described_class::REQUEST_EVENT) { |*, p| events << p } + example.run + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) + KB.config.request.retry_interval = 0.1 + KB.config.request.retries = 1 + end + + # Runs the call and returns what the caller saw plus how many HTTP attempts reached the stub. + def call(stub) + result = begin + yield + :ok + rescue Faraday::Error => e + e.class + end + { result: result, attempts: WebMock::RequestRegistry.instance.times_executed(stub.request_pattern) } + end + + it 'retries a GET after a connect timeout and reports the retry in the event' do + stub = stub_request(:get, 'http://kb.test/v1/pets/k').to_raise(Net::OpenTimeout).then.to_return(json) + + outcome = call(stub) { client.find('k') } + + expect(outcome.merge(event: events.last.slice(:status, :retries, :retry_errors))) + .to eq(result: :ok, attempts: 2, event: { status: 200, retries: 1, retry_errors: ['Net::OpenTimeout'] }) + end + + it 'retries a POST when the request never reached KB' do + stub = stub_request(:post, 'http://kb.test/v1/pets').to_raise(Errno::ECONNREFUSED).then.to_return(json) + + expect(call(stub) { client.create(name: 'Rex') }).to eq(result: :ok, attempts: 2) + end + + it 'does not retry a POST that may have reached KB' do + stub = stub_request(:post, 'http://kb.test/v1/pets').to_raise(Net::ReadTimeout).then.to_return(json) + + expect(call(stub) { client.create(name: 'Rex') }).to eq(result: Faraday::TimeoutError, attempts: 1) + end + + it 'retries a GET after a read timeout' do + stub = stub_request(:get, 'http://kb.test/v1/pets/k').to_raise(Net::ReadTimeout).then.to_return(json) + + expect(call(stub) { client.find('k') }).to eq(result: :ok, attempts: 2) + end + + it 'does not retry a read timeout on a call that set its own read_timeout' do + stub = stub_request(:get, 'http://kb.test/v1/pets/birthdays').to_raise(Net::ReadTimeout).then.to_return(json) + + expect(call(stub) { client.request('birthdays', read_timeout: 30) }) + .to eq(result: Faraday::TimeoutError, attempts: 1) + end + + it 'does not retry HTTP error responses' do + stub = stub_request(:get, 'http://kb.test/v1/pets/k').to_return(status: 503, body: '') + + expect(call(stub) { client.find('k') }).to eq(result: Faraday::ServerError, attempts: 1) + end + + it 'gives up after the configured retries and records the last error on the event' do + stub = stub_request(:get, 'http://kb.test/v1/pets/k').to_raise(Net::OpenTimeout) + + outcome = call(stub) { client.find('k') } + + expect(outcome.merge(retries: events.last[:retries], recorded: events.last[:exception_object].class)) + .to eq(result: Faraday::ConnectionFailed, attempts: 2, retries: 1, recorded: Faraday::ConnectionFailed) + end + + it 'does not retry when retries are set to 0' do + KB.config.request.retries = 0 + stub = stub_request(:get, 'http://kb.test/v1/pets/k').to_raise(Net::OpenTimeout).then.to_return(json) + + expect(call(stub) { client.find('k') }).to eq(result: Faraday::ConnectionFailed, attempts: 1) + end + + it 'leaves the event untouched when the first attempt succeeds' do + stub_request(:get, 'http://kb.test/v1/pets/k').to_return(json) + + client.find('k') + + expect(events.last).not_to include(:retries, :retry_errors) + end +end diff --git a/spec/instrumentation/datadog_spec.rb b/spec/instrumentation/datadog_spec.rb index 16ee90e2..abd6ef50 100644 --- a/spec/instrumentation/datadog_spec.rb +++ b/spec/instrumentation/datadog_spec.rb @@ -189,6 +189,36 @@ def resource(verb, path) end end + describe 'a retried call' do + around do |example| + KB.config.request.retry_interval = 0 + example.run + ensure + KB.config.request.retry_interval = 0.1 + end + + it 'tags the retry count and the retried error on an otherwise successful span' do + ok = { status: 200, body: '{}', headers: { 'Content-Type' => 'application/json' } } + stub_request(:get, 'http://kb.test/v1/pets/k').to_raise(Net::OpenTimeout).then.to_return(ok) + + client.find('k') + + expect( + status: last_span.status, retries: last_span.get_metric('kb.retries'), + errors: last_span.get_tag('kb.retry_errors') + ).to eq(status: 0, retries: 1, errors: 'Net::OpenTimeout') + end + + it 'adds no retry tags when the first attempt succeeds' do + stub_request(:get, 'http://kb.test/v1/pets/k').to_return(status: 200, body: '{}', + headers: { 'Content-Type' => 'application/json' }) + + client.find('k') + + expect(last_span.get_tag('kb.retries')).to be_nil + end + end + # The case that motivated this module: a connect failure never reaches # Net::HTTP#request, so the Datadog Net::HTTP tracer never sees it. The # notification wraps the connect and the span records it. @@ -218,9 +248,10 @@ def resource(verb, path) expect( raised: raised, status: last_span.status, error_type: last_span.get_tag('error.type'), - code: last_span.get_tag('http.status_code'), resource: last_span.resource + code: last_span.get_tag('http.status_code'), resource: last_span.resource, + retried: last_span.get_tag('kb.retry_errors') ).to eq(raised: Faraday::ConnectionFailed, status: 1, error_type: 'Faraday::ConnectionFailed', - code: nil, resource: 'GET /v1/pets/birthdays') + code: nil, resource: 'GET /v1/pets/birthdays', retried: 'Errno::ECONNREFUSED') end end end diff --git a/spec/models/concerns/listable_spec.rb b/spec/models/concerns/listable_spec.rb index 5d341015..a94ab880 100644 --- a/spec/models/concerns/listable_spec.rb +++ b/spec/models/concerns/listable_spec.rb @@ -48,4 +48,14 @@ expect { list }.to raise_exception api_exception end end + + context 'when the connection to KB fails' do + before do + allow(kb_client).to receive(:all).and_raise(Faraday::ConnectionFailed.new(Net::OpenTimeout.new)) + end + + it 'wraps it in KB::Error like every other Faraday error' do + expect { list }.to raise_exception(KB::Error) + end + end end diff --git a/spec/retry_policy_spec.rb b/spec/retry_policy_spec.rb new file mode 100644 index 00000000..3c78bd82 --- /dev/null +++ b/spec/retry_policy_spec.rb @@ -0,0 +1,41 @@ +require 'spec_helper' + +RSpec.describe KB::RetryPolicy do + verbs = %i[get head post patch put delete] + every_verb = verbs.to_h { |verb| [verb, true] } + get_and_head_only = verbs.to_h { |verb| [verb, %i[get head].include?(verb)] } + no_verb = verbs.to_h { |verb| [verb, false] } + + # Pins exactly which error x verb combinations retry. + { + 'connect timeout (net_http adapter)' => [-> { Faraday::ConnectionFailed.new(Net::OpenTimeout.new) }, every_verb], + 'connect timeout (persistent adapter)' => [-> { Faraday::TimeoutError.new(Net::OpenTimeout.new) }, every_verb], + 'connection refused' => [-> { Faraday::ConnectionFailed.new(Errno::ECONNREFUSED.new) }, every_verb], + 'host unreachable' => [-> { Faraday::ConnectionFailed.new(Errno::EHOSTUNREACH.new) }, every_verb], + 'DNS failure' => [-> { Faraday::ConnectionFailed.new(SocketError.new) }, every_verb], + 'read timeout' => [-> { Faraday::TimeoutError.new(Net::ReadTimeout.new) }, get_and_head_only], + 'write timeout' => [-> { Faraday::TimeoutError.new(Net::WriteTimeout.new) }, get_and_head_only], + 'connection reset' => [-> { Faraday::ConnectionFailed.new(Errno::ECONNRESET.new) }, get_and_head_only], + 'EOF while awaiting headers' => [-> { Faraday::ConnectionFailed.new(EOFError.new) }, get_and_head_only], + 'TLS error' => [-> { Faraday::SSLError.new(OpenSSL::SSL::SSLError.new) }, get_and_head_only], + 'HTTP 404' => [-> { Faraday::ResourceNotFound.new('not found') }, no_verb], + 'HTTP 500' => [-> { Faraday::ServerError.new('boom') }, no_verb] + }.each do |description, (build_error, expected)| + it "retries a #{description} for exactly the pinned verbs" do + error = build_error.call + expect(verbs.to_h { |verb| [verb, described_class.retry?(verb, error)] }).to eq(expected) + end + end + + context 'when the call set its own read budget' do + it 'still retries a failure that never reached KB' do + error = Faraday::ConnectionFailed.new(Net::OpenTimeout.new) + expect(described_class.retry?(:get, error, own_read_budget: true)).to be true + end + + it 'does not retry a read timeout, so the raised budget is not doubled' do + error = Faraday::TimeoutError.new(Net::ReadTimeout.new) + expect(described_class.retry?(:get, error, own_read_budget: true)).to be false + end + end +end