diff --git a/.changelog/bugfix-clock-skew-response-received-time.json b/.changelog/bugfix-clock-skew-response-received-time.json new file mode 100644 index 00000000000..0b511832d20 --- /dev/null +++ b/.changelog/bugfix-clock-skew-response-received-time.json @@ -0,0 +1,6 @@ +{ + "type": "bugfix", + "category": "aws-cpp-sdk-core", + "contributor": "", + "description": "Compute clock skew as the server Date minus the time the response headers were received, instead of the request round-trip midpoint, so long-running operations no longer record a false skew. The curl, CRT and WinHTTP/WinINet clients record the header arrival time; custom HTTP clients that do not set HttpRequest::SetResponseHeadersReceivedTime fall back to the time the request returned." +} diff --git a/src/aws-cpp-sdk-core/include/aws/core/http/HttpRequest.h b/src/aws-cpp-sdk-core/include/aws/core/http/HttpRequest.h index 020425e8294..69f429418ee 100644 --- a/src/aws-cpp-sdk-core/include/aws/core/http/HttpRequest.h +++ b/src/aws-cpp-sdk-core/include/aws/core/http/HttpRequest.h @@ -570,6 +570,23 @@ namespace Aws */ inline void SetSigningTimestampOverride(const Aws::Utils::DateTime& signingTime) { m_signingTimestampOverride = signingTime; } + /** + * Gets the raw client time (no skew applied) at which the final response's headers arrived for this attempt, if + * the HTTP client recorded it. + */ + inline const Aws::Crt::Optional& GetResponseHeadersReceivedTime() const { + return m_responseHeadersReceivedTime; + } + /** + * Records when the response headers arrived, before the body is read. Set by the HTTP client; used as the + * response-received time for clock-skew correction. + */ + inline void SetResponseHeadersReceivedTime(const Aws::Utils::DateTime& time) { m_responseHeadersReceivedTime = time; } + /** + * Clears the response headers received time; called at the start of each attempt. + */ + inline void ClearResponseHeadersReceivedTime() { m_responseHeadersReceivedTime.reset(); } + /** * Add a request metric * @param key, HttpClientMetricsKey defined in HttpClientMetrics.cpp @@ -631,6 +648,7 @@ namespace Aws ContinueRequestHandler m_continueRequest; Aws::String m_signingRegion; Aws::Crt::Optional m_signingTimestampOverride; + Aws::Crt::Optional m_responseHeadersReceivedTime; Aws::String m_signingAccessKey; Aws::String m_resolvedRemoteHost; Aws::Monitoring::HttpClientMetricsCollection m_httpRequestMetrics; diff --git a/src/aws-cpp-sdk-core/include/aws/core/internal/ClockSkew.h b/src/aws-cpp-sdk-core/include/aws/core/internal/ClockSkew.h index 2f921b83bac..e84abc4ccd9 100644 --- a/src/aws-cpp-sdk-core/include/aws/core/internal/ClockSkew.h +++ b/src/aws-cpp-sdk-core/include/aws/core/internal/ClockSkew.h @@ -78,9 +78,15 @@ namespace Aws return Aws::Crt::Optional{}; } - // Server Date is assumed to be from the round-trip midpoint (NTP offset, RFC 5905 s8). - const int64_t midpointMs = sentMs + (receivedMs - sentMs) / 2; - return Aws::Crt::Optional(std::chrono::milliseconds{serverMs - midpointMs}); + // The server's Date is compared with the moment its response headers reached the client. + return Aws::Crt::Optional(std::chrono::milliseconds{serverMs - receivedMs}); + } + + // Time the response headers arrived, if the HTTP client recorded it. Otherwise now (after the body), + // the legacy behaviour. + inline Aws::Utils::DateTime GetTimeResponseReceived(const Aws::Http::HttpRequest& request) { + const auto& stamped = request.GetResponseHeadersReceivedTime(); + return stamped.has_value() ? stamped.value() : Aws::Utils::DateTime::Now(); } // Clock-skew error codes. Matched by CoreErrors enum where one exists; AuthFailure (EC2) has no diff --git a/src/aws-cpp-sdk-core/source/client/AWSClient.cpp b/src/aws-cpp-sdk-core/source/client/AWSClient.cpp index 8455b59847e..ae6fb936579 100644 --- a/src/aws-cpp-sdk-core/source/client/AWSClient.cpp +++ b/src/aws-cpp-sdk-core/source/client/AWSClient.cpp @@ -327,8 +327,9 @@ HttpResponseOutcome AWSClient::AttemptExhaustively(const Aws::Http::URI& uri, const DateTime attemptSentTime = DateTime::Now(); httpRequest->SetSigningTimestampOverride(attemptSentTime + attemptSkew); + httpRequest->ClearResponseHeadersReceivedTime(); outcome = AttemptOneRequest(httpRequest, request, signerName, signerRegion, signerServiceNameOverride); - const DateTime timeResponseReceived = DateTime::Now(); + const DateTime timeResponseReceived = Aws::Internal::GetTimeResponseReceived(*httpRequest); outcome.SetRetryCount(retries); if (retries == 0) { @@ -508,8 +509,9 @@ HttpResponseOutcome AWSClient::AttemptExhaustively(const Aws::Http::URI& uri, }; const DateTime attemptSentTime = DateTime::Now(); httpRequest->SetSigningTimestampOverride(attemptSentTime + attemptSkew); + httpRequest->ClearResponseHeadersReceivedTime(); outcome = AttemptOneRequest(httpRequest, signerName, requestName, signerRegion, signerServiceNameOverride); - const DateTime timeResponseReceived = DateTime::Now(); + const DateTime timeResponseReceived = Aws::Internal::GetTimeResponseReceived(*httpRequest); outcome.SetRetryCount(retries); if (retries == 0) { @@ -814,6 +816,7 @@ std::shared_ptr AWSClient::StartOneAttemptAsync(const st context->attemptSentTime = DateTime::Now(); context->httpRequest->SetSigningTimestampOverride(context->attemptSentTime + context->attemptSkew); + context->httpRequest->ClearResponseHeadersReceivedTime(); const char* signerRegion = context->signerRegion ? context->signerRegion->c_str() : nullptr; const char* signerServiceName = context->signerServiceName ? context->signerServiceName->c_str() : nullptr; @@ -912,7 +915,7 @@ Http::HttpClient::AttemptOutcome AWSClient::OnAttemptCompleteAsync(const std::sh const Aws::AmazonWebServiceRequest& request = *context->request; HttpResponseOutcome outcome = std::move(outcomeParam); - const DateTime timeResponseReceived = DateTime::Now(); + const DateTime timeResponseReceived = Aws::Internal::GetTimeResponseReceived(*context->httpRequest); outcome.SetRetryCount(context->retries); if (context->retries == 0) { diff --git a/src/aws-cpp-sdk-core/source/http/crt/CRTHttpClient.cpp b/src/aws-cpp-sdk-core/source/http/crt/CRTHttpClient.cpp index 31fbd0ee390..47d0689479e 100644 --- a/src/aws-cpp-sdk-core/source/http/crt/CRTHttpClient.cpp +++ b/src/aws-cpp-sdk-core/source/http/crt/CRTHttpClient.cpp @@ -202,6 +202,11 @@ void OnClientConnectionAvailableAsync(const std::shared_ptrresponse); + // aws-c-http reports the main block done only when the body starts, so stamp as header lines arrive. + // Written on the event-loop thread and read in the completion callback on that same thread. + if (block == AWS_HTTP_HEADER_BLOCK_MAIN) { + state->request->SetResponseHeadersReceivedTime(Aws::Utils::DateTime::Now()); + } }; requestOptions.onIncomingHeadersBlockDone = [state](Aws::Crt::Http::HttpStream& stream, enum aws_http_header_block block) { @@ -292,9 +297,14 @@ class CRTConnection : public Aws::Http::Connection { Aws::Crt::Http::HttpRequestOptions requestOptions{}; requestOptions.request = crtRequest.get(); - requestOptions.onIncomingHeaders = [response](Aws::Crt::Http::HttpStream& stream, enum aws_http_header_block block, - const Aws::Crt::Http::HttpHeader* headersArray, std::size_t headersCount) { + requestOptions.onIncomingHeaders = [request, response](Aws::Crt::Http::HttpStream& stream, enum aws_http_header_block block, + const Aws::Crt::Http::HttpHeader* headersArray, std::size_t headersCount) { OnIncomingHeaders(stream, block, headersArray, headersCount, response); + // aws-c-http reports the main block done only when the body starts, so stamp as header lines arrive. + // Written on the event-loop thread; the caller reads it only after waiting for stream completion. + if (block == AWS_HTTP_HEADER_BLOCK_MAIN) { + request->SetResponseHeadersReceivedTime(Aws::Utils::DateTime::Now()); + } }; requestOptions.onIncomingHeadersBlockDone = [request, response](Aws::Crt::Http::HttpStream& stream, enum aws_http_header_block block) { diff --git a/src/aws-cpp-sdk-core/source/http/curl/CurlHttpClient.cpp b/src/aws-cpp-sdk-core/source/http/curl/CurlHttpClient.cpp index e8800631575..a954053d235 100644 --- a/src/aws-cpp-sdk-core/source/http/curl/CurlHttpClient.cpp +++ b/src/aws-cpp-sdk-core/source/http/curl/CurlHttpClient.cpp @@ -277,6 +277,10 @@ static size_t WriteHeader(char* ptr, size_t size, size_t nmemb, void* userdata) curl_easy_getinfo(context->m_curlHandle, CURLINFO_RESPONSE_CODE, &responseCode); response->SetResponseCode(static_cast(responseCode)); AWS_LOGSTREAM_DEBUG(CURL_HTTP_CLIENT_TAG, "Returned http response code " << responseCode); + // Last header block before the body wins, so a 1xx block is overwritten and trailers are ignored. + if (context->m_numBytesResponseReceived == 0) { + context->m_request->SetResponseHeadersReceivedTime(DateTime::Now()); + } auto& headersHandler = context->m_request->GetHeadersReceivedEventHandler(); if (headersHandler) { diff --git a/src/aws-cpp-sdk-core/source/http/windows/WinSyncHttpClient.cpp b/src/aws-cpp-sdk-core/source/http/windows/WinSyncHttpClient.cpp index 6e538e15237..f305cea59aa 100644 --- a/src/aws-cpp-sdk-core/source/http/windows/WinSyncHttpClient.cpp +++ b/src/aws-cpp-sdk-core/source/http/windows/WinSyncHttpClient.cpp @@ -191,6 +191,8 @@ bool WinSyncHttpClient::BuildSuccessResponse(const std::shared_ptr& Aws::StringStream ss; uint64_t read = 0; + // The platform has received the status line and headers by now, and the body is read below. + request->SetResponseHeadersReceivedTime(DateTime::Now()); DoQueryHeaders(hHttpRequest, response, ss, read); if(readLimiter != nullptr && read > 0) diff --git a/src/aws-cpp-sdk-core/source/smithy/client/AwsSmithyClientBase.cpp b/src/aws-cpp-sdk-core/source/smithy/client/AwsSmithyClientBase.cpp index 5893181de46..3cfa55bdd4d 100644 --- a/src/aws-cpp-sdk-core/source/smithy/client/AwsSmithyClientBase.cpp +++ b/src/aws-cpp-sdk-core/source/smithy/client/AwsSmithyClientBase.cpp @@ -495,6 +495,7 @@ std::shared_ptr AwsSmithyClientBase::AttemptOneRequestAs } pRequestCtx->m_timeRequestSent = Aws::Utils::DateTime::Now(); pRequestCtx->m_httpRequest->SetSigningTimestampOverride(pRequestCtx->m_timeRequestSent + pRequestCtx->m_attemptSkew); + pRequestCtx->m_httpRequest->ClearResponseHeadersReceivedTime(); SigningOutcome signingOutcome = TracingUtils::MakeCallWithTiming([&]() -> SigningOutcome { return this->SignHttpRequest(pRequestCtx->m_httpRequest, *pRequestCtx); }, @@ -572,7 +573,7 @@ Aws::Http::HttpClient::AttemptOutcome AwsSmithyClientBase::HandleAsyncReply(std: { assert(pRequestCtx && httpResponse); - pRequestCtx->m_timeResponseReceived = Aws::Utils::DateTime::Now(); + pRequestCtx->m_timeResponseReceived = Aws::Internal::GetTimeResponseReceived(*pRequestCtx->m_httpRequest); #if defined(AWS_CRT_HTTP_USE_ASYNC_IO) pRequestCtx->m_serviceCallTimer.reset(); #endif diff --git a/tests/aws-cpp-sdk-core-tests/aws/client/AWSClientTest.cpp b/tests/aws-cpp-sdk-core-tests/aws/client/AWSClientTest.cpp index e5ff090eb72..f1c224f09a5 100644 --- a/tests/aws-cpp-sdk-core-tests/aws/client/AWSClientTest.cpp +++ b/tests/aws-cpp-sdk-core-tests/aws/client/AWSClientTest.cpp @@ -312,6 +312,49 @@ TEST_F(AWSClientTestSuite, TestClockChangesAfterSkewHasBeenSet) ASSERT_EQ(1, client->GetRequestAttemptedRetries()); } +TEST_F(AWSClientTestSuite, TestClockSkewUsesResponseHeadersReceivedTime) { + // The HTTP client stamps the time the headers arrived, 3 seconds before the attempt returns (a slow body). + // The skew must be measured from the header time, not from when MakeRequest returned. + mockHttpClient->Reset(); + auto makeResponse = []() { + auto httpRequest = CreateHttpRequest(URI("http://www.uri.com/path/to/res"), HttpMethod::HTTP_GET, + Aws::Utils::Stream::DefaultResponseStreamFactoryMethod); + auto httpResponse = Aws::MakeShared(ALLOCATION_TAG, httpRequest); + httpResponse->SetResponseCode(HttpResponseCode::OK); + return httpResponse; + }; + auto firstResponse = makeResponse(); + mockHttpClient->AddResponseToReturn( + firstResponse, [](Aws::IOStream&) -> void {}, + [firstResponse](const std::shared_ptr& httpRequest) -> void { + // Whole seconds, so the 1 s resolution Date header carries exactly headersReceived + 1h. Back-dating the + // stamp by 3 s stands in for a slow body without sleeping. + const DateTime headersReceived(DateTime::Now().Millis() / 1000 * 1000 - 3000); + httpRequest->SetResponseHeadersReceivedTime(headersReceived); + firstResponse->AddHeader("Date", (headersReceived + std::chrono::hours(1)).ToGmtString(DateFormat::RFC822)); + }); + mockHttpClient->AddResponseToReturn(makeResponse(), [](Aws::IOStream&) -> void {}, [](const std::shared_ptr&) -> void {}); + + AmazonWebServiceRequestMock request; + auto outcome = client->MakeRequest(request); + AWS_ASSERT_SUCCESS(outcome); + + const DateTime before = DateTime::Now(); + outcome = client->MakeRequest(request); + const DateTime after = DateTime::Now(); + AWS_ASSERT_SUCCESS(outcome); + + // The second request is signed at its send time + exactly 1h; that send time lies between before and after. + // Measuring from when MakeRequest returned would give 1h - 3s instead. + const auto& requests = mockHttpClient->GetAllRequestsMade(); + ASSERT_EQ(2u, requests.size()); + const auto& signingTime = requests.back().GetSigningTimestampOverride(); + ASSERT_TRUE(signingTime.has_value()); + const DateTime sendTime = signingTime.value() - std::chrono::hours(1); + EXPECT_TRUE(before.Millis() <= sendTime.Millis() && sendTime.Millis() <= after.Millis()) + << "signing time should be the send time + exactly 1h"; +} + TEST_F(AWSClientTestSuite, TestRetryHeaders) { // The first server time is ahead of us by 1 hour. diff --git a/tests/aws-cpp-sdk-core-tests/resources/clock-skew-test-cases.json b/tests/aws-cpp-sdk-core-tests/resources/clock-skew-test-cases.json index 5ac9f44cd88..6ac16be669b 100644 --- a/tests/aws-cpp-sdk-core-tests/resources/clock-skew-test-cases.json +++ b/tests/aws-cpp-sdk-core-tests/resources/clock-skew-test-cases.json @@ -14,7 +14,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 00:00:01 GMT" + "Date": "Thu, 01 Jan 2026 00:00:02 GMT" } } } @@ -24,6 +24,73 @@ } ] }, + { + "description": "Long-running request does not attribute server processing time to ClientSkew", + "operations": [ + { + "initialClientSkew": 0, + "attempts": [ + { + "clientTimeAtSend": "2026-01-01T00:00:00Z", + "clientTimeAtReceive": "2026-01-01T00:10:20Z", + "expectedSigningTime": "2026-01-01T00:00:00Z", + "response": { + "statusCode": 200, + "headers": { + "Date": "Thu, 01 Jan 2026 00:10:20 GMT" + } + } + } + ], + "expectedClientSkew": 0, + "expectedOutcome": "success", + "documentation": "The request spends 620 seconds in server processing. The midpoint formula would record approximately +310 seconds, but comparing Date to response receipt time records no skew." + }, + { + "initialClientSkew": 0, + "attempts": [ + { + "clientTimeAtSend": "2026-01-01T00:10:21Z", + "clientTimeAtReceive": "2026-01-01T00:10:22Z", + "expectedSigningTime": "2026-01-01T00:10:21Z", + "response": { + "statusCode": 200, + "headers": { + "Date": "Thu, 01 Jan 2026 00:10:22 GMT" + } + } + } + ], + "expectedClientSkew": 0, + "expectedOutcome": "success", + "documentation": "The following operation is signed without a false offset from the preceding long-running request." + } + ] + }, + { + "description": "Response latency is attributed to ClientSkew", + "operations": [ + { + "initialClientSkew": 0, + "attempts": [ + { + "clientTimeAtSend": "2026-01-01T00:00:00Z", + "clientTimeAtReceive": "2026-01-01T00:00:02Z", + "expectedSigningTime": "2026-01-01T00:00:00Z", + "response": { + "statusCode": 200, + "headers": { + "Date": "Thu, 01 Jan 2026 00:00:01 GMT" + } + } + } + ], + "expectedClientSkew": -1, + "expectedOutcome": "success", + "documentation": "The response is generated when the clocks agree and takes one second to reach the client. Without a server transmit timestamp, that response latency is included in the candidate skew." + } + ] + }, { "description": "Definite clock skew error on first attempt, retry succeeds, ClientSkew persists to next operation", "operations": [ @@ -37,7 +104,7 @@ "response": { "statusCode": 403, "headers": { - "Date": "Thu, 01 Jan 2026 00:05:01 GMT" + "Date": "Thu, 01 Jan 2026 00:05:02 GMT" }, "errorCode": "RequestTimeTooSkewed" } @@ -49,7 +116,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 00:05:03 GMT" + "Date": "Thu, 01 Jan 2026 00:05:04 GMT" } } } @@ -67,7 +134,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 00:06:01 GMT" + "Date": "Thu, 01 Jan 2026 00:06:02 GMT" } } } @@ -91,7 +158,7 @@ "response": { "statusCode": 403, "headers": { - "Date": "Thu, 01 Jan 2026 00:05:01 GMT" + "Date": "Thu, 01 Jan 2026 00:05:02 GMT" }, "errorCode": "RequestTimeTooSkewed" } @@ -133,7 +200,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 00:22:01 GMT" + "Date": "Thu, 01 Jan 2026 00:22:02 GMT" } } } @@ -156,7 +223,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 00:00:01 GMT" + "Date": "Thu, 01 Jan 2026 00:00:02 GMT" } } } @@ -179,7 +246,7 @@ "response": { "statusCode": 400, "headers": { - "Date": "Thu, 01 Jan 2026 00:02:01 GMT" + "Date": "Thu, 01 Jan 2026 00:02:02 GMT" }, "errorCode": "InvalidSignatureException" } @@ -204,7 +271,7 @@ "response": { "statusCode": 400, "headers": { - "Date": "Thu, 01 Jan 2026 00:05:01 GMT" + "Date": "Thu, 01 Jan 2026 00:05:02 GMT" }, "errorCode": "InvalidSignatureException" } @@ -216,7 +283,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 00:05:03 GMT" + "Date": "Thu, 01 Jan 2026 00:05:04 GMT" } } } @@ -281,7 +348,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 16:56:11 GMT" + "Date": "Thu, 01 Jan 2026 16:56:12 GMT" } } } @@ -325,7 +392,7 @@ "response": { "statusCode": 200, "headers": { - "Date": "Thu, 01 Jan 2026 16:51:11 GMT" + "Date": "Thu, 01 Jan 2026 16:51:12 GMT" } } } diff --git a/tests/aws-cpp-sdk-core-tests/utils/ClockSkewTest.cpp b/tests/aws-cpp-sdk-core-tests/utils/ClockSkewTest.cpp index 046c78e76c0..704a9cd6f57 100644 --- a/tests/aws-cpp-sdk-core-tests/utils/ClockSkewTest.cpp +++ b/tests/aws-cpp-sdk-core-tests/utils/ClockSkewTest.cpp @@ -54,7 +54,7 @@ class ClockSkewTest : public Aws::Testing::AwsCppSdkGTestSuite, public testing:: public: static const size_t TEST_CASE_COUNT; }; -const size_t ClockSkewTest::TEST_CASE_COUNT = 10; +const size_t ClockSkewTest::TEST_CASE_COUNT = 12; TEST_P(ClockSkewTest, RunTestCase) {