From d16c134a4cd81714e5a06e6b64e9123f007690d8 Mon Sep 17 00:00:00 2001 From: Siddharth Srivastava Date: Sun, 1 Nov 2026 23:41:37 +0000 Subject: [PATCH 1/3] fix: compute clock skew from the time response headers are received --- gems/aws-sdk-core/CHANGELOG.md | 2 + .../plugins/retries/clock_skew.rb | 30 ++- .../lib/aws-sdk-core/plugins/retry_errors.rb | 2 + .../aws/plugins/retries/clock_skew_spec.rb | 150 ++++++++++-- .../retries/clock_skew_test_cases_spec.rb | 229 ++++++++++++++++++ .../aws/plugins/retry_errors_legacy_spec.rb | 16 ++ 6 files changed, 399 insertions(+), 30 deletions(-) create mode 100644 gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb diff --git a/gems/aws-sdk-core/CHANGELOG.md b/gems/aws-sdk-core/CHANGELOG.md index 5ece7579064..0b7cb3a1ab0 100644 --- a/gems/aws-sdk-core/CHANGELOG.md +++ b/gems/aws-sdk-core/CHANGELOG.md @@ -1,6 +1,8 @@ Unreleased Changes ------------------ +* Issue - Compute clock skew corrections from the time response headers are received instead of the request round-trip midpoint, so long-running requests no longer record server processing time as clock skew. + 3.263.0 (2026-10-29) ------------------ diff --git a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb index 19cf7f0f026..78cc39c0b15 100644 --- a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb +++ b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb @@ -39,7 +39,7 @@ def estimated_skew(endpoint) # Whether a response indicates skew large enough to warrant a retry; records nothing. # @param context [Seahorse::Client::RequestContext] - # @param sent_at [Time, nil] raw (pre-skew) send time, for the midpoint calculation + # @param sent_at [Time, nil] raw (pre-skew) send time, to discard slow requests def clock_skewed?(context, sent_at = nil) candidate = candidate_skew(context, sent_at) !!candidate && candidate.abs > CLOCK_SKEW_THRESHOLD @@ -47,7 +47,7 @@ def clock_skewed?(context, sent_at = nil) # Called on every response; records the skew candidate when one can be computed. # @param context [Seahorse::Client::RequestContext] - # @param sent_at [Time, nil] raw (pre-skew) send time, for the midpoint calculation + # @param sent_at [Time, nil] raw (pre-skew) send time, to discard slow requests def update_clock_correction(context, sent_at = nil) candidate = candidate_skew(context, sent_at) return if candidate.nil? @@ -71,26 +71,38 @@ def update_estimated_skew(context) end end + # Called at the start of every attempt. Records the raw client time at + # which the attempt's response headers arrive, before the body is read. + # Retries reuse the same response, so the listener is added only once. + # @param context [Seahorse::Client::RequestContext] + def track_response_received_at(context) + context.metadata.delete(:clock_skew_response_received_at) + return unless context.retries.zero? + + context.http_response.on_headers do + context.metadata[:clock_skew_response_received_at] = Time.now.utc + end + end + private # Single source of truth for skew computation; returns a Float skew or nil. + # The candidate is the server Date minus the time the response headers were + # received (the current time if that was not recorded). # @param context [Seahorse::Client::RequestContext] - # @param sent_at [Time, nil] raw (pre-skew) send time; midpoint when present, else server - now + # @param sent_at [Time, nil] raw (pre-skew) send time; used only to discard slow requests # @return [Float, nil] def candidate_skew(context, sent_at = nil) response = context.http_response server_time = server_time(response) # No candidate if the Date header is absent/unparseable or the response was cached. return nil if server_time.nil? || response.headers['age'] - return server_time - Time.now.utc unless sent_at - received_at = Time.now.utc - elapsed = received_at - sent_at + received_at = context.metadata[:clock_skew_response_received_at] || Time.now.utc # Discard if the request was too slow for the measurement to be trusted. - return nil if elapsed > MAX_TRUSTED_REQUEST_DURATION + return nil if sent_at && received_at - sent_at > MAX_TRUSTED_REQUEST_DURATION - # Midpoint formula (NTP clock offset, RFC 5905 section 8). - server_time - (sent_at + (elapsed / 2.0)) + server_time - received_at end ## diff --git a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb index 1492529c2cd..703e897407f 100644 --- a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb +++ b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb @@ -294,6 +294,7 @@ class Handler < Seahorse::Client::Handler def call(context) context.metadata[:retries] ||= {} config = context.config + config.clock_skew.track_response_received_at(context) get_send_token(config) add_retry_headers(context) @@ -492,6 +493,7 @@ def compute_request_ttl(context) class LegacyHandler < Seahorse::Client::Handler def call(context) + context.config.clock_skew.track_response_received_at(context) response = with_metric { @handler.call(context) } if response.error error_inspector = Retries::ErrorInspector.new( diff --git a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb index d2fda577fc1..614f442973c 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb @@ -10,18 +10,17 @@ module Plugins # @param endpoint [URI, String] the endpoint the request points at # @param server_time [String, nil] the timestamp returned by the server def build_context(endpoint, server_time) - response = double('response', headers: { 'date' => server_time }) - request = double('request', endpoint: endpoint) - - double('context', http_response: response, http_request: request) + build_context_with_headers(endpoint, 'date' => server_time) end - # Builds a context whose response carries arbitrary headers (e.g. 'age'). - def build_context_with_headers(endpoint, headers) + # Builds a context whose response carries arbitrary headers (e.g. 'age') + # and, optionally, the time the response headers were received. + def build_context_with_headers(endpoint, headers, received_at = nil) response = double('response', headers: headers) request = double('request', endpoint: endpoint) + metadata = { clock_skew_response_received_at: received_at } - double('context', http_response: response, http_request: request) + double('context', http_response: response, http_request: request, metadata: metadata) end subject { Retries::ClockSkew.new } @@ -391,20 +390,129 @@ def build_context_with_headers(endpoint, headers) end end - describe 'candidate skew (midpoint + guards)' do - describe '#update_clock_correction with a send time' do - it 'uses the midpoint formula to discount network transit' do - sent_at = Time.now.utc - # server generated its Date 100s ahead of the client, response takes 10s - server_time = (sent_at + 100).httpdate - ctx = build_context_with_headers(endpoint, 'date' => server_time) - allow(Time).to receive(:now).and_return(sent_at.getlocal + 10) + describe 'candidate skew (server Date - response headers received time)' do + let(:t) { Time.utc(2026, 1, 1) } - subject.update_clock_correction(ctx, sent_at) - # midpoint = sent_at + 5s, so skew ~= 100 - 5 = 95s - expect(subject.clock_correction(endpoint)).to be_within(1).of(95) - end + # Records one response and returns the stored correction. + def correction_for(date:, received_at:, sent_at: t, endpoint: 'https://example.com') + headers = date ? { 'date' => date.httpdate } : {} + ctx = build_context_with_headers(endpoint, headers, received_at) + subject.update_clock_correction(ctx, sent_at) + subject.clock_correction(endpoint) + end + + it 'is 0 when the clocks agree' do + expect(correction_for(date: t + 2, received_at: t + 2)).to eq(0) + end + + it 'is positive when the server clock is ahead' do + expect(correction_for(date: t + 3602, received_at: t + 2)).to eq(3600) + end + + it 'is negative when the server clock is behind' do + expect(correction_for(date: t - 3598, received_at: t + 2)).to eq(-3600) + end + + it 'is 0 for a 620s request when the clocks agree (midpoint would give +310s)' do + expect(correction_for(date: t + 620, received_at: t + 620)).to eq(0) + end + + it 'is +600s for a 620s request when the server clock is 10 minutes ahead' do + expect(correction_for(date: t + 1220, received_at: t + 620)).to eq(600) + end + + it 'attributes response latency to skew' do + expect(correction_for(date: t + 1, received_at: t + 2)).to eq(-1) + end + + it 'keeps a round trip of exactly 900s' do + expect(correction_for(date: t + 4500, received_at: t + 900)).to eq(3600) + end + + it 'discards a round trip of 901s' do + expect(correction_for(date: t + 4501, received_at: t + 901)).to eq(0) + end + it 'discards a response without a Date header' do + expect(correction_for(date: nil, received_at: t + 2)).to eq(0) + end + + it 'discards a cached response with an Age header' do + ctx = build_context_with_headers( + endpoint, { 'date' => (t + 3602).httpdate, 'age' => '30' }, t + 2 + ) + subject.update_clock_correction(ctx, t) + expect(subject.clock_correction(endpoint)).to eq(0) + expect(subject.clock_skewed?(ctx, t)).to be false + end + + it 'uses the headers received time, not the current time' do + # The body finished 10 seconds after the headers arrived. + allow(Time).to receive(:now).and_return((t + 12).getlocal) + expect(correction_for(date: t + 3602, received_at: t + 2)).to eq(3600) + end + + it 'uses the headers received time for the max trusted duration check' do + # Headers at 899s are trusted even though the body finished after 901s. + allow(Time).to receive(:now).and_return((t + 901).getlocal) + expect(correction_for(date: t + 899, received_at: t + 899)).to eq(0) + expect(correction_for(date: t + 4499, received_at: t + 899)).to eq(3600) + end + + it 'uses the headers received time for clock_skewed?' do + allow(Time).to receive(:now).and_return((t + 1000).getlocal) + # server - headers received = 241s; server - now would be -757s. + above = build_context_with_headers(endpoint, { 'date' => (t + 243).httpdate }, t + 2) + below = build_context_with_headers(endpoint, { 'date' => (t + 241).httpdate }, t + 2) + expect(subject.clock_skewed?(above, t)).to be true + expect(subject.clock_skewed?(below, t)).to be false + end + + it 'records the correction per endpoint' do + expect(correction_for(date: t + 3602, received_at: t + 2, endpoint: 'https://a.example.com')).to eq(3600) + expect(correction_for(date: t + 2, received_at: t + 2, endpoint: 'https://b.example.com')).to eq(0) + expect(subject.clock_correction('https://a.example.com')).to eq(3600) + end + end + + describe '#track_response_received_at' do + let(:t) { Time.utc(2026, 1, 1) } + let(:http_response) { Seahorse::Client::Http::Response.new } + let(:ctx) { Seahorse::Client::RequestContext.new(http_response: http_response) } + + it 'records the raw time the response headers arrive' do + subject.track_response_received_at(ctx) + expect(ctx.metadata[:clock_skew_response_received_at]).to be_nil + + allow(Time).to receive(:now).and_return((t + 2).getlocal) + http_response.signal_headers(200, 'date' => (t + 3602).httpdate) + allow(Time).to receive(:now).and_return((t + 10).getlocal) + http_response.signal_data('body') + http_response.signal_done + + expect(ctx.metadata[:clock_skew_response_received_at]).to eq(t + 2) + expect(ctx.metadata[:clock_skew_response_received_at]).to be_utc + end + + it 'clears the previous attempt time and adds the listener only once' do + subject.track_response_received_at(ctx) + http_response.signal_headers(200, {}) + expect(ctx.metadata[:clock_skew_response_received_at]).not_to be_nil + + ctx.retries += 1 + http_response.reset + subject.track_response_received_at(ctx) + expect(ctx.metadata[:clock_skew_response_received_at]).to be_nil + expect(http_response.instance_variable_get(:@listeners)[:headers].size).to eq(1) + + allow(Time).to receive(:now).and_return((t + 5).getlocal) + http_response.signal_headers(200, {}) + expect(ctx.metadata[:clock_skew_response_received_at]).to eq(t + 5) + end + end + + describe 'candidate skew (guards)' do + describe '#update_clock_correction with a send time' do it 'discards the candidate when elapsed exceeds the max trusted duration' do sent_at = Time.now.utc server_time = (sent_at + 100).httpdate @@ -461,8 +569,8 @@ def build_context_with_headers(endpoint, headers) end end - describe 'legacy fallback (no send time)' do - it 'computes skew as server_time - now' do + describe 'no headers received time recorded' do + it 'falls back to server_time - now' do server_time = (Time.now.utc + 1000).to_s ctx = build_context_with_headers(endpoint, 'date' => server_time) subject.update_clock_correction(ctx) diff --git a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb new file mode 100644 index 00000000000..15b7425cb51 --- /dev/null +++ b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb @@ -0,0 +1,229 @@ +# frozen_string_literal: true + +require_relative '../../../spec_helper' +require 'socket' + +module Aws + module Plugins + # Shared clock skew correction test cases, run through a real client with a + # fake clock: the clock reads the attempt's send time while the request is + # signed, and its receive time when the response headers arrive. + describe 'clock skew correction test cases' do + # Builds an attempt; times are HH:MM:SS on 2026-01-01 UTC. + def self.attempt(send, receive, signing, status, date, error_code = nil, age: nil) + time = ->(hms) { Time.parse("2026-01-01T#{hms}Z").utc } + headers = {} + headers['Date'] = "Thu, 01 Jan 2026 #{date} GMT" if date + headers['Age'] = age if age + { + send: time.call(send), receive: time.call(receive), signing: time.call(signing), + status: status, headers: headers, error_code: error_code + } + end + + def self.operation(initial_skew, expected_skew, outcome, attempts, max_attempts: nil) + { initial_skew: initial_skew, expected_skew: expected_skew, outcome: outcome, + attempts: attempts, max_attempts: max_attempts } + end + + TEST_CASES = { + 'Clocks agree, request succeeds on first attempt, ClientSkew updated to 0' => [ + operation(0, 0, :success, [attempt('00:00:00', '00:00:02', '00:00:00', 200, '00:00:02')]) + ], + 'Long-running request does not attribute server processing time to ClientSkew' => [ + operation(0, 0, :success, [attempt('00:00:00', '00:10:20', '00:00:00', 200, '00:10:20')]), + operation(0, 0, :success, [attempt('00:10:21', '00:10:22', '00:10:21', 200, '00:10:22')]) + ], + 'Response latency is attributed to ClientSkew' => [ + operation(0, -1, :success, [attempt('00:00:00', '00:00:02', '00:00:00', 200, '00:00:01')]) + ], + 'Definite clock skew error on first attempt, retry succeeds, ClientSkew persists to next operation' => [ + operation(0, 300, :success, [ + attempt('00:00:00', '00:00:02', '00:00:00', 403, '00:05:02', 'RequestTimeTooSkewed'), + attempt('00:00:02', '00:00:04', '00:05:02', 200, '00:05:04') + ]), + operation(300, 300, :success, [attempt('00:01:00', '00:01:02', '00:06:00', 200, '00:06:02')]) + ], + 'Clock skew error with no retry budget still updates ClientSkew' => [ + operation(0, 300, :error, [ + attempt('00:00:00', '00:00:02', '00:00:00', 403, '00:05:02', 'RequestTimeTooSkewed') + ], max_attempts: 1) + ], + 'Delayed response exceeding trust threshold does not update ClientSkew' => [ + operation(0, 0, :success, [attempt('00:00:00', '00:16:00', '00:00:00', 200, '00:10:00')]), + operation(0, 300, :success, [attempt('00:17:00', '00:17:02', '00:17:00', 200, '00:22:02')]) + ], + 'Stale ClientSkew is silently corrected by a successful response without error or retry' => [ + operation(300, 0, :success, [attempt('00:00:00', '00:00:02', '00:05:00', 200, '00:00:02')]) + ], + 'Possible clock skew error with skew below detection threshold is not retried as clock skew' => [ + operation(0, 120, :error, [ + attempt('00:00:00', '00:00:02', '00:00:00', 400, '00:02:02', 'InvalidSignatureException') + ]) + ], + 'Possible clock skew error with skew above detection threshold is retried and succeeds' => [ + operation(0, 300, :success, [ + attempt('00:00:00', '00:00:02', '00:00:00', 400, '00:05:02', 'InvalidSignatureException'), + attempt('00:00:02', '00:00:04', '00:05:02', 200, '00:05:04') + ]) + ], + 'Clock skew error with no Date header is not treated as a candidate, ClientSkew is not updated' => [ + operation(0, 0, :error, [ + attempt('00:00:00', '00:00:02', '00:00:00', 403, nil, 'RequestTimeTooSkewed') + ]) + ], + 'Cached response with Age header does not update ClientSkew' => [ + operation(0, 0, :success, [ + attempt('16:51:00', '16:51:02', '16:51:00', 200, '12:03:01', age: '17280') + ]), + operation(0, 300, :success, [attempt('16:51:10', '16:51:12', '16:51:10', 200, '16:56:12')]) + ], + 'Cached response with Age header does not poison ClientSkew even when followed by a clock skew error' => [ + operation(0, 0, :success, [ + attempt('16:51:00', '16:51:02', '16:51:00', 200, '12:03:01', age: '17280') + ]), + operation(0, 0, :success, [attempt('16:51:10', '16:51:12', '16:51:10', 200, '16:51:12')]) + ] + }.freeze + + let(:client) do + Aws::STS::Client.new( + region: 'us-east-1', + credentials: Credentials.new('akid', 'secret'), + retry_mode: 'standard' + ) + end + let(:endpoint) { 'https://sts.us-east-1.amazonaws.com' } + let(:clock_skew) { client.config.clock_skew } + + # Fake clock and the attempts of the operation being run; shared with the + # send handler, which does not run in the example's scope. + let(:state) { { now: Time.now.utc } } + + before do + allow(Kernel).to receive(:sleep) + state = self.state + allow(Time).to receive(:now) { state[:now].getlocal } + body_for = method(:body_for) + client.handle(step: :send) do |context| + attempts = state[:attempts] + signing_times = state[:signing_times] + attempt = attempts[signing_times.size] + signing_times << context.http_request.headers['X-Amz-Date'] + state[:now] = attempt[:receive] + context.http_response.signal_headers(attempt[:status], attempt[:headers]) + context.http_response.signal_data(body_for.call(attempt)) + context.http_response.signal_done + # The clock moves on before the response is processed, so the + # correction must come from the time the headers arrived. + state[:now] = attempts[signing_times.size]&.dig(:send) || attempt[:receive] + 5 + Seahorse::Client::Response.new(context: context) + end + end + + def body_for(attempt) + if attempt[:error_code] + 'Sender' \ + "#{attempt[:error_code]}m" \ + 'id' + else + '' \ + '123456789012' \ + '' + end + end + + # Runs one operation; returns its outcome and each attempt's signing time. + def run_operation(operation) + state[:attempts] = operation[:attempts] + state[:signing_times] = [] + state[:now] = operation[:attempts].first[:send] + client.config.max_attempts = operation[:max_attempts] || 3 + client.get_caller_identity + [:success, state[:signing_times]] + rescue Aws::STS::Errors::ServiceError + [:error, state[:signing_times]] + end + + TEST_CASES.each do |description, operations| + it description do + operations.each_with_index do |operation, i| + if i.zero? + clock_skew.send(:set_clock_correction, endpoint, operation[:initial_skew]) + end + expect(clock_skew.clock_correction(endpoint)).to eq(operation[:initial_skew]) + + outcome, signing_times = run_operation(operation) + + expected_signing = operation[:attempts].map { |a| a[:signing].strftime('%Y%m%dT%H%M%SZ') } + expect(signing_times).to eq(expected_signing) + expect(outcome).to eq(operation[:outcome]) + expect(clock_skew.clock_correction(endpoint)).to eq(operation[:expected_skew]) + end + end + end + end + + # Runs against a loopback server over the real Net::HTTP transport. The + # server sends a Date one hour ahead, then holds the body back, so the + # correction is about +3600s only if it uses the time the headers arrived. + describe 'clock skew correction over Net::HTTP' do + body_delay = 2 + + # WebMock's Net::HTTP adapter reads the whole body before yielding the + # response, so turn it off to exercise the real transport. + before { WebMock.disable! } + after { WebMock.enable! } + + define_method(:serve_once) do |server, status, body| + Thread.new do + socket = server.accept + length = 0 + while (line = socket.gets) && line != "\r\n" + length = line.split(':', 2).last.to_i if line =~ /\Acontent-length:/i + end + socket.read(length) + socket.write( + "HTTP/1.1 #{status} X\r\nDate: #{(Time.now.utc + 3600).httpdate}\r\n" \ + "Content-Type: text/xml\r\nContent-Length: #{body.bytesize}\r\n" \ + "Connection: close\r\n\r\n" + ) + socket.flush + sleep(body_delay) + socket.write(body) + socket.close + end + end + + { + 200 => '' \ + '123456789012' \ + '', + 403 => 'SenderRequestTimeTooSkewed' \ + 'mid' + }.each do |status, body| + it "uses the time the headers arrived for a #{status} response" do + server = TCPServer.new('127.0.0.1', 0) + endpoint = "http://127.0.0.1:#{server.addr[1]}" + thread = serve_once(server, status, body) + client = Aws::STS::Client.new( + region: 'us-east-1', endpoint: endpoint, retry_mode: 'standard', + max_attempts: 1, credentials: Credentials.new('akid', 'secret') + ) + + begin + client.get_caller_identity + rescue Aws::STS::Errors::RequestTimeTooSkewed + raise unless status == 403 + end + + # With the body-done time this would be about 3600 - body_delay. + expect(client.config.clock_skew.clock_correction(endpoint)).to be_within(1).of(3600) + ensure + thread&.join + server&.close + end + end + end + end +end diff --git a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb index 7e8a91b7902..761dfec9a50 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb @@ -225,6 +225,22 @@ module Plugins expect(resp.context.retries).to eq(1) end + it 'detects clock skew from the time the response headers arrived' do + t = Time.utc(2026, 1, 1) + resp.error = RetryErrorsSvc::Errors::RequestTimeTooSkewed.new(nil, nil) + handle do |context| + # server - headers received = 248s (above the 4 minute threshold); + # server - body done = 230s (below it). + allow(Time).to receive(:now).and_return((t + 2).getlocal) + context.http_response.signal_headers(403, 'date' => (t + 250).httpdate) + allow(Time).to receive(:now).and_return((t + 20).getlocal) + context.http_response.signal_done + resp + end + expect(resp.context.retries).to eq(3) + expect(resp.context.http_response.instance_variable_get(:@listeners)[:headers].size).to eq(1) + end + it 'retries if endpoint discovery error is detected' do config.api.endpoint_operation = :describe_endpoints DescribeEndpointsRequest = Seahorse::Model::Shapes::StructureShape.new( From 5bf0c47463996ff03b9864342d01968a7469bd1c Mon Sep 17 00:00:00 2001 From: terajul Date: Tue, 3 Nov 2026 16:20:32 +0000 Subject: [PATCH 2/3] Refine clock skew response timing and regression coverage --- build_tools/services.rb | 4 +- gems/aws-sdk-core/CHANGELOG.md | 2 +- .../plugins/retries/clock_skew.rb | 15 +- .../lib/aws-sdk-core/plugins/retry_errors.rb | 16 +- .../aws/plugins/retries/clock_skew_spec.rb | 122 ++-------- .../retries/clock_skew_test_cases_spec.rb | 229 ------------------ .../aws/plugins/retry_errors_legacy_spec.rb | 24 +- .../spec/aws/plugins/retry_errors_spec.rb | 119 +++++++++ 8 files changed, 167 insertions(+), 364 deletions(-) delete mode 100644 gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb diff --git a/build_tools/services.rb b/build_tools/services.rb index 60948d95e46..dd39e571b8c 100644 --- a/build_tools/services.rb +++ b/build_tools/services.rb @@ -9,10 +9,10 @@ class ServiceEnumerator MANIFEST_PATH = File.expand_path('../../services.json', __FILE__) # Minimum `aws-sdk-core` version for new gem builds - MINIMUM_CORE_VERSION = "3.263.0" + MINIMUM_CORE_VERSION = "3.264.0" # Minimum `aws-sdk-core` version for new S3 gem builds - MINIMUM_CORE_VERSION_S3 = "3.263.0" + MINIMUM_CORE_VERSION_S3 = "3.264.0" EVENTSTREAM_PLUGIN = "Aws::Plugins::EventStreamConfiguration" diff --git a/gems/aws-sdk-core/CHANGELOG.md b/gems/aws-sdk-core/CHANGELOG.md index 0b7cb3a1ab0..1051d679b1c 100644 --- a/gems/aws-sdk-core/CHANGELOG.md +++ b/gems/aws-sdk-core/CHANGELOG.md @@ -1,7 +1,7 @@ Unreleased Changes ------------------ -* Issue - Compute clock skew corrections from the time response headers are received instead of the request round-trip midpoint, so long-running requests no longer record server processing time as clock skew. +* Feature - Improve clock skew correction accuracy for long-running requests and slow response downloads. 3.263.0 (2026-10-29) ------------------ diff --git a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb index 78cc39c0b15..c63d6cbbcdb 100644 --- a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb +++ b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retries/clock_skew.rb @@ -71,19 +71,6 @@ def update_estimated_skew(context) end end - # Called at the start of every attempt. Records the raw client time at - # which the attempt's response headers arrive, before the body is read. - # Retries reuse the same response, so the listener is added only once. - # @param context [Seahorse::Client::RequestContext] - def track_response_received_at(context) - context.metadata.delete(:clock_skew_response_received_at) - return unless context.retries.zero? - - context.http_response.on_headers do - context.metadata[:clock_skew_response_received_at] = Time.now.utc - end - end - private # Single source of truth for skew computation; returns a Float skew or nil. @@ -98,7 +85,7 @@ def candidate_skew(context, sent_at = nil) # No candidate if the Date header is absent/unparseable or the response was cached. return nil if server_time.nil? || response.headers['age'] - received_at = context.metadata[:clock_skew_response_received_at] || Time.now.utc + received_at = context.metadata[:response_received_at] || Time.now.utc # Discard if the request was too slow for the measurement to be trusted. return nil if sent_at && received_at - sent_at > MAX_TRUSTED_REQUEST_DURATION diff --git a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb index 703e897407f..b68fd0e2752 100644 --- a/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb +++ b/gems/aws-sdk-core/lib/aws-sdk-core/plugins/retry_errors.rb @@ -177,6 +177,16 @@ class RetryErrors < Seahorse::Client::Plugin DYNAMODB_SERVICES = Set['DynamoDB', 'DynamoDB Streams'].freeze class << self + # @api private + # HTTP retries preserve the listener, so register it only once. + def track_response_time(context) + return unless context.retries.zero? + + context.http_response.on_headers do + context.metadata[:response_received_at] = Time.now.utc + end + end + # TODO: Remove this gate and hardcode new retry behavior once # AWS_NEW_RETRIES_2026 is enabled by default, which includes: # - Default retry_mode to 'standard' @@ -294,7 +304,7 @@ class Handler < Seahorse::Client::Handler def call(context) context.metadata[:retries] ||= {} config = context.config - config.clock_skew.track_response_received_at(context) + RetryErrors.track_response_time(context) get_send_token(config) add_retry_headers(context) @@ -452,6 +462,7 @@ def retry_request(context, error) context.config.credentials.refresh! if refresh_credentials?(context, error) context.http_request.body.rewind context.http_response.reset + context.metadata.delete(:response_received_at) call(context) end @@ -493,7 +504,7 @@ def compute_request_ttl(context) class LegacyHandler < Seahorse::Client::Handler def call(context) - context.config.clock_skew.track_response_received_at(context) + RetryErrors.track_response_time(context) response = with_metric { @handler.call(context) } if response.error error_inspector = Retries::ErrorInspector.new( @@ -532,6 +543,7 @@ def retry_request(context, error) context.config.credentials.refresh! if refresh_credentials?(context, error) context.http_request.body.rewind context.http_response.reset + context.metadata.delete(:response_received_at) call(context) end diff --git a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb index 614f442973c..9e035559be1 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb @@ -18,7 +18,7 @@ def build_context(endpoint, server_time) def build_context_with_headers(endpoint, headers, received_at = nil) response = double('response', headers: headers) request = double('request', endpoint: endpoint) - metadata = { clock_skew_response_received_at: received_at } + metadata = { response_received_at: received_at } double('context', http_response: response, http_request: request, metadata: metadata) end @@ -390,124 +390,32 @@ def build_context_with_headers(endpoint, headers, received_at = nil) end end - describe 'candidate skew (server Date - response headers received time)' do + describe 'response headers arrival time' do let(:t) { Time.utc(2026, 1, 1) } - # Records one response and returns the stored correction. - def correction_for(date:, received_at:, sent_at: t, endpoint: 'https://example.com') - headers = date ? { 'date' => date.httpdate } : {} - ctx = build_context_with_headers(endpoint, headers, received_at) - subject.update_clock_correction(ctx, sent_at) - subject.clock_correction(endpoint) - end - - it 'is 0 when the clocks agree' do - expect(correction_for(date: t + 2, received_at: t + 2)).to eq(0) - end - - it 'is positive when the server clock is ahead' do - expect(correction_for(date: t + 3602, received_at: t + 2)).to eq(3600) - end - - it 'is negative when the server clock is behind' do - expect(correction_for(date: t - 3598, received_at: t + 2)).to eq(-3600) - end - - it 'is 0 for a 620s request when the clocks agree (midpoint would give +310s)' do - expect(correction_for(date: t + 620, received_at: t + 620)).to eq(0) - end - - it 'is +600s for a 620s request when the server clock is 10 minutes ahead' do - expect(correction_for(date: t + 1220, received_at: t + 620)).to eq(600) - end - - it 'attributes response latency to skew' do - expect(correction_for(date: t + 1, received_at: t + 2)).to eq(-1) - end - - it 'keeps a round trip of exactly 900s' do - expect(correction_for(date: t + 4500, received_at: t + 900)).to eq(3600) - end + it 'uses headers arrival to correct skew after a long-running request' do + allow(Time).to receive(:now).and_return(t + 630) + ctx = build_context_with_headers(endpoint, { 'date' => (t + 1220).httpdate }, t + 620) - it 'discards a round trip of 901s' do - expect(correction_for(date: t + 4501, received_at: t + 901)).to eq(0) - end - - it 'discards a response without a Date header' do - expect(correction_for(date: nil, received_at: t + 2)).to eq(0) - end - - it 'discards a cached response with an Age header' do - ctx = build_context_with_headers( - endpoint, { 'date' => (t + 3602).httpdate, 'age' => '30' }, t + 2 - ) subject.update_clock_correction(ctx, t) - expect(subject.clock_correction(endpoint)).to eq(0) - expect(subject.clock_skewed?(ctx, t)).to be false - end - it 'uses the headers received time, not the current time' do - # The body finished 10 seconds after the headers arrived. - allow(Time).to receive(:now).and_return((t + 12).getlocal) - expect(correction_for(date: t + 3602, received_at: t + 2)).to eq(3600) + expect(subject.clock_correction(endpoint)).to eq(600) end - it 'uses the headers received time for the max trusted duration check' do - # Headers at 899s are trusted even though the body finished after 901s. - allow(Time).to receive(:now).and_return((t + 901).getlocal) - expect(correction_for(date: t + 899, received_at: t + 899)).to eq(0) - expect(correction_for(date: t + 4499, received_at: t + 899)).to eq(3600) - end - - it 'uses the headers received time for clock_skewed?' do - allow(Time).to receive(:now).and_return((t + 1000).getlocal) - # server - headers received = 241s; server - now would be -757s. - above = build_context_with_headers(endpoint, { 'date' => (t + 243).httpdate }, t + 2) - below = build_context_with_headers(endpoint, { 'date' => (t + 241).httpdate }, t + 2) - expect(subject.clock_skewed?(above, t)).to be true - expect(subject.clock_skewed?(below, t)).to be false - end + it 'trusts headers received within the duration limit even when the body finishes later' do + allow(Time).to receive(:now).and_return(t + 901) + ctx = build_context_with_headers(endpoint, { 'date' => (t + 4499).httpdate }, t + 899) - it 'records the correction per endpoint' do - expect(correction_for(date: t + 3602, received_at: t + 2, endpoint: 'https://a.example.com')).to eq(3600) - expect(correction_for(date: t + 2, received_at: t + 2, endpoint: 'https://b.example.com')).to eq(0) - expect(subject.clock_correction('https://a.example.com')).to eq(3600) - end - end - - describe '#track_response_received_at' do - let(:t) { Time.utc(2026, 1, 1) } - let(:http_response) { Seahorse::Client::Http::Response.new } - let(:ctx) { Seahorse::Client::RequestContext.new(http_response: http_response) } - - it 'records the raw time the response headers arrive' do - subject.track_response_received_at(ctx) - expect(ctx.metadata[:clock_skew_response_received_at]).to be_nil - - allow(Time).to receive(:now).and_return((t + 2).getlocal) - http_response.signal_headers(200, 'date' => (t + 3602).httpdate) - allow(Time).to receive(:now).and_return((t + 10).getlocal) - http_response.signal_data('body') - http_response.signal_done + subject.update_clock_correction(ctx, t) - expect(ctx.metadata[:clock_skew_response_received_at]).to eq(t + 2) - expect(ctx.metadata[:clock_skew_response_received_at]).to be_utc + expect(subject.clock_correction(endpoint)).to eq(3600) end - it 'clears the previous attempt time and adds the listener only once' do - subject.track_response_received_at(ctx) - http_response.signal_headers(200, {}) - expect(ctx.metadata[:clock_skew_response_received_at]).not_to be_nil - - ctx.retries += 1 - http_response.reset - subject.track_response_received_at(ctx) - expect(ctx.metadata[:clock_skew_response_received_at]).to be_nil - expect(http_response.instance_variable_get(:@listeners)[:headers].size).to eq(1) + it 'uses headers arrival to decide whether skew exceeds the retry threshold' do + allow(Time).to receive(:now).and_return(t + 1000) + ctx = build_context_with_headers(endpoint, { 'date' => (t + 241).httpdate }, t + 2) - allow(Time).to receive(:now).and_return((t + 5).getlocal) - http_response.signal_headers(200, {}) - expect(ctx.metadata[:clock_skew_response_received_at]).to eq(t + 5) + expect(subject.clock_skewed?(ctx, t)).to be(false) end end diff --git a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb deleted file mode 100644 index 15b7425cb51..00000000000 --- a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_test_cases_spec.rb +++ /dev/null @@ -1,229 +0,0 @@ -# frozen_string_literal: true - -require_relative '../../../spec_helper' -require 'socket' - -module Aws - module Plugins - # Shared clock skew correction test cases, run through a real client with a - # fake clock: the clock reads the attempt's send time while the request is - # signed, and its receive time when the response headers arrive. - describe 'clock skew correction test cases' do - # Builds an attempt; times are HH:MM:SS on 2026-01-01 UTC. - def self.attempt(send, receive, signing, status, date, error_code = nil, age: nil) - time = ->(hms) { Time.parse("2026-01-01T#{hms}Z").utc } - headers = {} - headers['Date'] = "Thu, 01 Jan 2026 #{date} GMT" if date - headers['Age'] = age if age - { - send: time.call(send), receive: time.call(receive), signing: time.call(signing), - status: status, headers: headers, error_code: error_code - } - end - - def self.operation(initial_skew, expected_skew, outcome, attempts, max_attempts: nil) - { initial_skew: initial_skew, expected_skew: expected_skew, outcome: outcome, - attempts: attempts, max_attempts: max_attempts } - end - - TEST_CASES = { - 'Clocks agree, request succeeds on first attempt, ClientSkew updated to 0' => [ - operation(0, 0, :success, [attempt('00:00:00', '00:00:02', '00:00:00', 200, '00:00:02')]) - ], - 'Long-running request does not attribute server processing time to ClientSkew' => [ - operation(0, 0, :success, [attempt('00:00:00', '00:10:20', '00:00:00', 200, '00:10:20')]), - operation(0, 0, :success, [attempt('00:10:21', '00:10:22', '00:10:21', 200, '00:10:22')]) - ], - 'Response latency is attributed to ClientSkew' => [ - operation(0, -1, :success, [attempt('00:00:00', '00:00:02', '00:00:00', 200, '00:00:01')]) - ], - 'Definite clock skew error on first attempt, retry succeeds, ClientSkew persists to next operation' => [ - operation(0, 300, :success, [ - attempt('00:00:00', '00:00:02', '00:00:00', 403, '00:05:02', 'RequestTimeTooSkewed'), - attempt('00:00:02', '00:00:04', '00:05:02', 200, '00:05:04') - ]), - operation(300, 300, :success, [attempt('00:01:00', '00:01:02', '00:06:00', 200, '00:06:02')]) - ], - 'Clock skew error with no retry budget still updates ClientSkew' => [ - operation(0, 300, :error, [ - attempt('00:00:00', '00:00:02', '00:00:00', 403, '00:05:02', 'RequestTimeTooSkewed') - ], max_attempts: 1) - ], - 'Delayed response exceeding trust threshold does not update ClientSkew' => [ - operation(0, 0, :success, [attempt('00:00:00', '00:16:00', '00:00:00', 200, '00:10:00')]), - operation(0, 300, :success, [attempt('00:17:00', '00:17:02', '00:17:00', 200, '00:22:02')]) - ], - 'Stale ClientSkew is silently corrected by a successful response without error or retry' => [ - operation(300, 0, :success, [attempt('00:00:00', '00:00:02', '00:05:00', 200, '00:00:02')]) - ], - 'Possible clock skew error with skew below detection threshold is not retried as clock skew' => [ - operation(0, 120, :error, [ - attempt('00:00:00', '00:00:02', '00:00:00', 400, '00:02:02', 'InvalidSignatureException') - ]) - ], - 'Possible clock skew error with skew above detection threshold is retried and succeeds' => [ - operation(0, 300, :success, [ - attempt('00:00:00', '00:00:02', '00:00:00', 400, '00:05:02', 'InvalidSignatureException'), - attempt('00:00:02', '00:00:04', '00:05:02', 200, '00:05:04') - ]) - ], - 'Clock skew error with no Date header is not treated as a candidate, ClientSkew is not updated' => [ - operation(0, 0, :error, [ - attempt('00:00:00', '00:00:02', '00:00:00', 403, nil, 'RequestTimeTooSkewed') - ]) - ], - 'Cached response with Age header does not update ClientSkew' => [ - operation(0, 0, :success, [ - attempt('16:51:00', '16:51:02', '16:51:00', 200, '12:03:01', age: '17280') - ]), - operation(0, 300, :success, [attempt('16:51:10', '16:51:12', '16:51:10', 200, '16:56:12')]) - ], - 'Cached response with Age header does not poison ClientSkew even when followed by a clock skew error' => [ - operation(0, 0, :success, [ - attempt('16:51:00', '16:51:02', '16:51:00', 200, '12:03:01', age: '17280') - ]), - operation(0, 0, :success, [attempt('16:51:10', '16:51:12', '16:51:10', 200, '16:51:12')]) - ] - }.freeze - - let(:client) do - Aws::STS::Client.new( - region: 'us-east-1', - credentials: Credentials.new('akid', 'secret'), - retry_mode: 'standard' - ) - end - let(:endpoint) { 'https://sts.us-east-1.amazonaws.com' } - let(:clock_skew) { client.config.clock_skew } - - # Fake clock and the attempts of the operation being run; shared with the - # send handler, which does not run in the example's scope. - let(:state) { { now: Time.now.utc } } - - before do - allow(Kernel).to receive(:sleep) - state = self.state - allow(Time).to receive(:now) { state[:now].getlocal } - body_for = method(:body_for) - client.handle(step: :send) do |context| - attempts = state[:attempts] - signing_times = state[:signing_times] - attempt = attempts[signing_times.size] - signing_times << context.http_request.headers['X-Amz-Date'] - state[:now] = attempt[:receive] - context.http_response.signal_headers(attempt[:status], attempt[:headers]) - context.http_response.signal_data(body_for.call(attempt)) - context.http_response.signal_done - # The clock moves on before the response is processed, so the - # correction must come from the time the headers arrived. - state[:now] = attempts[signing_times.size]&.dig(:send) || attempt[:receive] + 5 - Seahorse::Client::Response.new(context: context) - end - end - - def body_for(attempt) - if attempt[:error_code] - 'Sender' \ - "#{attempt[:error_code]}m" \ - 'id' - else - '' \ - '123456789012' \ - '' - end - end - - # Runs one operation; returns its outcome and each attempt's signing time. - def run_operation(operation) - state[:attempts] = operation[:attempts] - state[:signing_times] = [] - state[:now] = operation[:attempts].first[:send] - client.config.max_attempts = operation[:max_attempts] || 3 - client.get_caller_identity - [:success, state[:signing_times]] - rescue Aws::STS::Errors::ServiceError - [:error, state[:signing_times]] - end - - TEST_CASES.each do |description, operations| - it description do - operations.each_with_index do |operation, i| - if i.zero? - clock_skew.send(:set_clock_correction, endpoint, operation[:initial_skew]) - end - expect(clock_skew.clock_correction(endpoint)).to eq(operation[:initial_skew]) - - outcome, signing_times = run_operation(operation) - - expected_signing = operation[:attempts].map { |a| a[:signing].strftime('%Y%m%dT%H%M%SZ') } - expect(signing_times).to eq(expected_signing) - expect(outcome).to eq(operation[:outcome]) - expect(clock_skew.clock_correction(endpoint)).to eq(operation[:expected_skew]) - end - end - end - end - - # Runs against a loopback server over the real Net::HTTP transport. The - # server sends a Date one hour ahead, then holds the body back, so the - # correction is about +3600s only if it uses the time the headers arrived. - describe 'clock skew correction over Net::HTTP' do - body_delay = 2 - - # WebMock's Net::HTTP adapter reads the whole body before yielding the - # response, so turn it off to exercise the real transport. - before { WebMock.disable! } - after { WebMock.enable! } - - define_method(:serve_once) do |server, status, body| - Thread.new do - socket = server.accept - length = 0 - while (line = socket.gets) && line != "\r\n" - length = line.split(':', 2).last.to_i if line =~ /\Acontent-length:/i - end - socket.read(length) - socket.write( - "HTTP/1.1 #{status} X\r\nDate: #{(Time.now.utc + 3600).httpdate}\r\n" \ - "Content-Type: text/xml\r\nContent-Length: #{body.bytesize}\r\n" \ - "Connection: close\r\n\r\n" - ) - socket.flush - sleep(body_delay) - socket.write(body) - socket.close - end - end - - { - 200 => '' \ - '123456789012' \ - '', - 403 => 'SenderRequestTimeTooSkewed' \ - 'mid' - }.each do |status, body| - it "uses the time the headers arrived for a #{status} response" do - server = TCPServer.new('127.0.0.1', 0) - endpoint = "http://127.0.0.1:#{server.addr[1]}" - thread = serve_once(server, status, body) - client = Aws::STS::Client.new( - region: 'us-east-1', endpoint: endpoint, retry_mode: 'standard', - max_attempts: 1, credentials: Credentials.new('akid', 'secret') - ) - - begin - client.get_caller_identity - rescue Aws::STS::Errors::RequestTimeTooSkewed - raise unless status == 403 - end - - # With the body-done time this would be about 3600 - body_delay. - expect(client.config.clock_skew.clock_correction(endpoint)).to be_within(1).of(3600) - ensure - thread&.join - server&.close - end - end - end - end -end diff --git a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb index 761dfec9a50..a24eb6f21e0 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_legacy_spec.rb @@ -225,20 +225,26 @@ module Plugins expect(resp.context.retries).to eq(1) end - it 'detects clock skew from the time the response headers arrived' do + it 'retries clock skew errors using headers arrival before body completion' do t = Time.utc(2026, 1, 1) - resp.error = RetryErrorsSvc::Errors::RequestTimeTooSkewed.new(nil, nil) + config.retry_limit = 1 handle do |context| - # server - headers received = 248s (above the 4 minute threshold); - # server - body done = 230s (below it). - allow(Time).to receive(:now).and_return((t + 2).getlocal) - context.http_response.signal_headers(403, 'date' => (t + 250).httpdate) - allow(Time).to receive(:now).and_return((t + 20).getlocal) + if context.retries.zero? + # Skew is 248s at headers arrival, but only 230s at body completion. + allow(Time).to receive(:now).and_return(t + 2) + context.http_response.signal_headers(403, 'date' => (t + 250).httpdate) + allow(Time).to receive(:now).and_return(t + 20) + resp.error = RetryErrorsSvc::Errors::RequestTimeTooSkewed.new(nil, nil) + else + context.http_response.signal_headers(200, {}) + resp.error = nil + end context.http_response.signal_done resp end - expect(resp.context.retries).to eq(3) - expect(resp.context.http_response.instance_variable_get(:@listeners)[:headers].size).to eq(1) + + expect(resp.context.retries).to eq(1) + expect(resp.error).to be_nil end it 'retries if endpoint discovery error is detected' do diff --git a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb index b198a537304..a5779319a56 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb @@ -148,6 +148,90 @@ module Plugins ) expect(c.config.disable_clock_skew_correction).to eq(true) end + + context 'clock skew correction through a client' do + let(:now) { Time.utc(2026, 1, 1) } + let(:send_handler) { double('send handler') } + let(:client) do + Aws::STS::Client.new( + region: 'us-east-1', retry_mode: 'standard', + credentials: Credentials.new('akid', 'secret') + ) + end + let(:endpoint) { 'https://sts.us-east-1.amazonaws.com' } + + before do + allow(Time).to receive(:now).and_return(now) + allow(Kernel).to receive(:sleep) + send_handler = self.send_handler + client.handle(step: :send) { |context| send_handler.call(context) } + end + + def respond(context, received_at:, server_time:, body_finished_at: received_at, error_code: nil) + allow(Time).to receive(:now).and_return(received_at) + context.http_response.signal_headers( + error_code ? 403 : 200, 'date' => server_time.httpdate + ) + allow(Time).to receive(:now).and_return(body_finished_at) + body = if error_code + 'Sender' \ + "#{error_code}m" \ + 'id' + else + '' \ + '123456789012' \ + '' + end + context.http_response.signal_data(body) + context.http_response.signal_done + Seahorse::Client::Response.new(context: context) + end + + it 'does not interpret a long-running request as clock skew' do + allow(send_handler).to receive(:call) do |context| + respond(context, received_at: now + 620, server_time: now + 620) + end + + client.get_caller_identity + + expect(client.config.clock_skew.clock_correction(endpoint)).to eq(0) + end + + it 'uses headers arrival to correct skew even when an error body arrives later' do + client.config.max_attempts = 1 + allow(send_handler).to receive(:call) do |context| + respond( + context, received_at: now + 2, server_time: now + 302, + body_finished_at: now + 20, error_code: 'RequestTimeTooSkewed' + ) + end + + expect { client.get_caller_identity }.to raise_error(Aws::STS::Errors::RequestTimeTooSkewed) + expect(client.config.clock_skew.clock_correction(endpoint)).to eq(300) + end + + it 'signs the retry and later operations with the learned correction' do + expect(send_handler).to receive(:call).ordered do |context| + expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000000Z') + respond( + context, received_at: now + 2, server_time: now + 302, + error_code: 'RequestTimeTooSkewed' + ) + end + expect(send_handler).to receive(:call).ordered do |context| + expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000502Z') + respond(context, received_at: now + 4, server_time: now + 304) + end + expect(send_handler).to receive(:call).ordered do |context| + expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000600Z') + respond(context, received_at: now + 62, server_time: now + 362) + end + + client.get_caller_identity + allow(Time).to receive(:now).and_return(now + 60) + client.get_caller_identity + end + end end describe RetryErrors::Handler do @@ -184,6 +268,41 @@ module Plugins resp.context.operation = operation end + it 'corrects clock skew using headers arrival before the response body finishes' do + t = Time.utc(2026, 1, 1) + handle do |context| + allow(Time).to receive(:now).and_return((t + 2).getlocal) + context.http_response.signal_headers(200, 'date' => (t + 3602).httpdate) + allow(Time).to receive(:now).and_return((t + 10).getlocal) + context.http_response.signal_data('body') + context.http_response.signal_done + resp + end + + expect(config.clock_skew.clock_correction(resp.context.http_request.endpoint)).to eq(3600) + end + + it 'clears the previous attempt timestamp before receiving retry headers' do + t = Time.utc(2026, 1, 1) + handle do |context| + expect(context.metadata[:response_received_at]).to be_nil + if context.retries.zero? + allow(Time).to receive(:now).and_return((t + 2).getlocal) + context.http_response.signal_headers(500, {}) + resp.error = service_error + else + allow(Time).to receive(:now).and_return((t + 5).getlocal) + context.http_response.signal_headers(200, {}) + resp.error = nil + end + context.http_response.signal_done + resp + end + + expect(resp.context.retries).to eq(1) + expect(resp.context.metadata[:response_received_at]).to eq(t + 5) + end + context 'standard mode' do before(:each) do allow(RetryErrors).to receive(:new_retries?).and_return(true) From 6f4afa9c117043eae64d79ee65b01f66d28d9ae4 Mon Sep 17 00:00:00 2001 From: terajul Date: Tue, 3 Nov 2026 16:30:32 +0000 Subject: [PATCH 3/3] Simplify clock skew regression specs --- .../aws/plugins/retries/clock_skew_spec.rb | 9 ------- .../spec/aws/plugins/retry_errors_spec.rb | 27 +++++++------------ 2 files changed, 9 insertions(+), 27 deletions(-) diff --git a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb index 9e035559be1..871d0b46343 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retries/clock_skew_spec.rb @@ -393,15 +393,6 @@ def build_context_with_headers(endpoint, headers, received_at = nil) describe 'response headers arrival time' do let(:t) { Time.utc(2026, 1, 1) } - it 'uses headers arrival to correct skew after a long-running request' do - allow(Time).to receive(:now).and_return(t + 630) - ctx = build_context_with_headers(endpoint, { 'date' => (t + 1220).httpdate }, t + 620) - - subject.update_clock_correction(ctx, t) - - expect(subject.clock_correction(endpoint)).to eq(600) - end - it 'trusts headers received within the duration limit even when the body finishes later' do allow(Time).to receive(:now).and_return(t + 901) ctx = build_context_with_headers(endpoint, { 'date' => (t + 4499).httpdate }, t + 899) diff --git a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb index a5779319a56..90166536921 100644 --- a/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb +++ b/gems/aws-sdk-core/spec/aws/plugins/retry_errors_spec.rb @@ -187,7 +187,11 @@ def respond(context, received_at:, server_time:, body_finished_at: received_at, Seahorse::Client::Response.new(context: context) end - it 'does not interpret a long-running request as clock skew' do + it 'replaces a stale correction with zero after a long-running request' do + clock_skew = client.config.clock_skew + clock_skew.send(:set_clock_correction, endpoint, -300) + expect(clock_skew.clock_correction(endpoint)).to eq(-300) + allow(send_handler).to receive(:call) do |context| respond(context, received_at: now + 620, server_time: now + 620) end @@ -197,30 +201,17 @@ def respond(context, received_at:, server_time:, body_finished_at: received_at, expect(client.config.clock_skew.clock_correction(endpoint)).to eq(0) end - it 'uses headers arrival to correct skew even when an error body arrives later' do - client.config.max_attempts = 1 - allow(send_handler).to receive(:call) do |context| - respond( - context, received_at: now + 2, server_time: now + 302, - body_finished_at: now + 20, error_code: 'RequestTimeTooSkewed' - ) - end - - expect { client.get_caller_identity }.to raise_error(Aws::STS::Errors::RequestTimeTooSkewed) - expect(client.config.clock_skew.clock_correction(endpoint)).to eq(300) - end - - it 'signs the retry and later operations with the learned correction' do + it 'signs the retry and later operations using headers arrival despite a delayed error body' do expect(send_handler).to receive(:call).ordered do |context| expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000000Z') respond( context, received_at: now + 2, server_time: now + 302, - error_code: 'RequestTimeTooSkewed' + body_finished_at: now + 20, error_code: 'RequestTimeTooSkewed' ) end expect(send_handler).to receive(:call).ordered do |context| - expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000502Z') - respond(context, received_at: now + 4, server_time: now + 304) + expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000520Z') + respond(context, received_at: now + 22, server_time: now + 322) end expect(send_handler).to receive(:call).ordered do |context| expect(context.http_request.headers['X-Amz-Date']).to eq('20260101T000600Z')