diff --git a/.changes/next-release/bugfix-AWSSDKforJavav2-c3201a9.json b/.changes/next-release/bugfix-AWSSDKforJavav2-c3201a9.json new file mode 100644 index 000000000000..103cbd162118 --- /dev/null +++ b/.changes/next-release/bugfix-AWSSDKforJavav2-c3201a9.json @@ -0,0 +1,6 @@ +{ + "type": "bugfix", + "category": "AWS SDK for Java v2", + "contributor": "", + "description": "Fix `ApiCallDuration` so that it measures the whole API call. It previously started after marshalling had already completed, and on asynchronous clients it also started after endpoint resolution, auth scheme resolution, request compression and checksum computation, and so understated the reported duration. The metric is now measured identically for synchronous and asynchronous clients and matches the documented formula. Reported `ApiCallDuration` values will increase but do not reflect changes in actual round-trip latency." +} diff --git a/core/sdk-core/pom.xml b/core/sdk-core/pom.xml index bca2a785cca7..34409b8d5e96 100644 --- a/core/sdk-core/pom.xml +++ b/core/sdk-core/pom.xml @@ -267,7 +267,10 @@ japicmp-maven-plugin - + + software.amazon.awssdk.core.spi.identity.AuthSchemeOptionsResolver#resolve(software.amazon.awssdk.core.SdkRequest) diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/client/config/ClientOverrideConfiguration.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/client/config/ClientOverrideConfiguration.java index 04c418c1b08d..7a79c4b60bfb 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/client/config/ClientOverrideConfiguration.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/client/config/ClientOverrideConfiguration.java @@ -288,6 +288,9 @@ public Optional scheduledExecutorService() { * execution except for marshalling. This includes request handler execution, all HTTP requests including retries, * unmarshalling, etc. This value should always be positive, if present. * + *

Because this window is narrower than the API call as a whole, the reported + * {@link software.amazon.awssdk.core.metrics.CoreMetric#API_CALL_DURATION} metric can exceed this timeout. + * *

The api call timeout feature doesn't have strict guarantees on how quickly a request is aborted when the * timeout is breached. The typical case aborts the request within a few milliseconds but there may occasionally be * requests that don't get aborted until several seconds after the timer has been breached. Because of this, the client @@ -613,6 +616,9 @@ default Builder retryStrategy(Consumer> configurator * entire client execution except for marshalling. This includes request handler execution, all HTTP requests including * retries, unmarshalling, etc. This value should always be positive, if present. * + *

Because this window is narrower than the API call as a whole, the reported + * {@link software.amazon.awssdk.core.metrics.CoreMetric#API_CALL_DURATION} metric can exceed this timeout. + * *

The api call timeout feature doesn't have strict guarantees on how quickly a request is aborted when the * timeout is breached. The typical case aborts the request within a few milliseconds but there may occasionally be * requests that don't get aborted until several seconds after the timer has been breached. Because of this, the client diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseAsyncClientHandler.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseAsyncClientHandler.java index 0c2f91a3a424..4e27f2400c18 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseAsyncClientHandler.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseAsyncClientHandler.java @@ -17,6 +17,7 @@ import static software.amazon.awssdk.utils.FunctionalUtils.runAndLogError; +import java.time.Duration; import java.util.Optional; import java.util.concurrent.CompletableFuture; import java.util.function.Function; @@ -50,6 +51,7 @@ import software.amazon.awssdk.http.SdkHttpFullRequest; import software.amazon.awssdk.http.SdkHttpFullResponse; import software.amazon.awssdk.metrics.MetricCollector; +import software.amazon.awssdk.metrics.NoOpMetricCollector; import software.amazon.awssdk.utils.CompletableFutureUtils; import software.amazon.awssdk.utils.Logger; @@ -70,7 +72,7 @@ protected BaseAsyncClientHandler(SdkClientConfiguration clientConfiguration, public CompletableFuture execute( ClientExecutionParams executionParams) { - return measureApiCallSuccess(executionParams, () -> { + return measureApiCall(executionParams, () -> { // Running beforeExecution interceptors and modifyRequest interceptors. ExecutionContext executionContext = invokeInterceptorsAndCreateExecutionContext(executionParams); @@ -86,7 +88,7 @@ public Complet ClientExecutionParams executionParams, AsyncResponseTransformer asyncResponseTransformer) { - return measureApiCallSuccess(executionParams, () -> { + return measureApiCall(executionParams, () -> { if (executionParams.getCombinedResponseHandler() != null) { // There is no support for catching errors in a body for streaming responses. Our codegen must never // attempt to do this. @@ -232,7 +234,10 @@ private Comple new AsyncAfterTransmissionInterceptorCallingResponseHandler<>(asyncResponseHandler, executionContext)); + // Captured because the requestBody branch above may reassign 'marshalled', leaving it not effectively final. + SdkHttpFullRequest requestForMetrics = marshalled; CompletableFuture exceptionTranslatedFuture = invokeFuture.handle((resp, err) -> { + reportServiceEndpointMetric(executionContext, requestForMetrics); if (err != null) { throw ThrowableUtils.failure(err); } @@ -288,27 +293,49 @@ private CompletableFuture invoke( .execute(responseHandler); } - private CompletableFuture measureApiCallSuccess(ClientExecutionParams executionParams, - Supplier> apiCall) { + /** + * Measure {@link CoreMetric#API_CALL_DURATION} and report {@link CoreMetric#API_CALL_SUCCESSFUL} for the whole API + * call. + * + *

The window deliberately encloses everything the SDK does for the call, marshalling included, and closes when + * the returned future completes. Measuring inside the request pipeline is not an option: the pipeline's input is the + * already-marshalled request, so no arrangement of pipeline stages can enclose marshalling. Measuring here also + * keeps the window identical to the synchronous client's. + */ + private CompletableFuture measureApiCall(ClientExecutionParams executionParams, + Supplier> apiCall) { + MetricCollector metricCollector = executionParams.getMetricCollector(); + if (metricCollector == null || metricCollector instanceof NoOpMetricCollector) { + // Nothing will consume these metrics, so don't pay for the clock reads or the extra future. A null collector + // is treated the same as NoOp: when the params carry none, the collector that AwsExecutionContextBuilder + // substitutes into the ExecutionContext is never handed to a publisher, so anything reported to it is + // discarded. + try { + return apiCall.get(); + } catch (Exception e) { + return CompletableFutureUtils.failedFuture(e); + } + } + + long callStart = System.nanoTime(); try { CompletableFuture apiCallResult = apiCall.get(); CompletableFuture outputFuture = - apiCallResult.whenComplete((r, t) -> reportApiCallSuccess(executionParams, t == null)); + apiCallResult.whenComplete((r, t) -> reportApiCallMetrics(metricCollector, callStart, t == null)); // Preserve cancellations on the output future, by passing cancellations of the output future to the api call future. CompletableFutureUtils.forwardExceptionTo(outputFuture, apiCallResult); return outputFuture; } catch (Exception e) { - reportApiCallSuccess(executionParams, false); + reportApiCallMetrics(metricCollector, callStart, false); return CompletableFutureUtils.failedFuture(e); } } - private void reportApiCallSuccess(ClientExecutionParams executionParams, boolean value) { - MetricCollector metricCollector = executionParams.getMetricCollector(); - if (metricCollector != null) { - metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, value); - } + private void reportApiCallMetrics(MetricCollector metricCollector, long callStartNanoTime, boolean successful) { + long durationNanos = System.nanoTime() - callStartNanoTime; + metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, successful); + metricCollector.reportMetric(CoreMetric.API_CALL_DURATION, Duration.ofNanos(durationNanos)); } } diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseClientHandler.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseClientHandler.java index 3c7f2d58a2a8..25fdc1459873 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseClientHandler.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseClientHandler.java @@ -90,6 +90,22 @@ static InterceptorContext finalizeSdkHttpFu return runModifyHttpRequestAndHttpContentInterceptors(executionContext); } + /** + * Report the {@link CoreMetric#SERVICE_ENDPOINT} metric for a completed request execution. + * + *

This must run after the request pipeline, so that {@code EndpointResolutionStage} and the signer have applied + * their changes to the HTTP request held by the interceptor context. {@code fallbackRequest} is used only when the + * interceptor context does not hold a full request, which can happen when the execution failed before the pipeline + * updated it. + */ + static void reportServiceEndpointMetric(ExecutionContext executionContext, SdkHttpFullRequest fallbackRequest) { + SdkHttpRequest finalRequest = executionContext.interceptorContext().httpRequest(); + MetricUtils.collectServiceEndpointMetrics(executionContext.metricCollector(), + finalRequest instanceof SdkHttpFullRequest + ? (SdkHttpFullRequest) finalRequest + : fallbackRequest); + } + private static void runBeforeMarshallingInterceptors(ExecutionContext executionContext) { executionContext.interceptorChain().beforeMarshalling(executionContext.interceptorContext(), executionContext.executionAttributes()); diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseSyncClientHandler.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseSyncClientHandler.java index 03ea0683397b..2a4d20f88ed3 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseSyncClientHandler.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/handler/BaseSyncClientHandler.java @@ -15,6 +15,7 @@ package software.amazon.awssdk.core.internal.handler; +import java.time.Duration; import java.util.Optional; import java.util.function.Supplier; import software.amazon.awssdk.annotations.SdkInternalApi; @@ -41,6 +42,7 @@ import software.amazon.awssdk.http.SdkHttpFullRequest; import software.amazon.awssdk.http.SdkHttpFullResponse; import software.amazon.awssdk.metrics.MetricCollector; +import software.amazon.awssdk.metrics.NoOpMetricCollector; @SdkInternalApi public abstract class BaseSyncClientHandler extends BaseClientHandler implements SyncClientHandler { @@ -57,7 +59,7 @@ public ReturnT ClientExecutionParams executionParams, ResponseTransformer responseTransformer) { - return measureApiCallSuccess(executionParams, () -> { + return measureApiCall(executionParams, () -> { // Running beforeExecution interceptors and modifyRequest interceptors. ExecutionContext executionContext = invokeInterceptorsAndCreateExecutionContext(executionParams); @@ -71,7 +73,7 @@ public ReturnT public OutputT execute( ClientExecutionParams executionParams) { - return measureApiCallSuccess(executionParams, () -> { + return measureApiCall(executionParams, () -> { // Running beforeExecution interceptors and modifyRequest interceptors. ExecutionContext executionContext = invokeInterceptorsAndCreateExecutionContext(executionParams); @@ -170,28 +172,44 @@ private ReturnT doExecute( } SdkClientConfiguration clientConfiguration = resolveRequestConfiguration(executionParams); - return invoke(clientConfiguration, - marshalled, - inputT, - executionContext, - responseHandler); + try { + return invoke(clientConfiguration, + marshalled, + inputT, + executionContext, + responseHandler); + } finally { + reportServiceEndpointMetric(executionContext, marshalled); + } } - private T measureApiCallSuccess(ClientExecutionParams executionParams, Supplier thingToMeasureSuccessOf) { + /** + * Measure {@link CoreMetric#API_CALL_DURATION} and report {@link CoreMetric#API_CALL_SUCCESSFUL} for the whole API + * call. + * + *

The window deliberately encloses everything the SDK does for the call, marshalling included. Measuring inside + * the request pipeline is not an option: the pipeline's input is the already-marshalled request, so no arrangement + * of pipeline stages can enclose marshalling. + */ + private T measureApiCall(ClientExecutionParams executionParams, Supplier apiCall) { + MetricCollector metricCollector = executionParams.getMetricCollector(); + if (metricCollector == null || metricCollector instanceof NoOpMetricCollector) { + // Nothing will consume these metrics, so don't pay for the clock reads. A null collector is treated the same + // as NoOp: when the params carry none, the collector that AwsExecutionContextBuilder substitutes into the + // ExecutionContext is never handed to a publisher, so anything reported to it is discarded. + return apiCall.get(); + } + + long callStart = System.nanoTime(); try { - T result = thingToMeasureSuccessOf.get(); - reportApiCallSuccess(executionParams, true); + T result = apiCall.get(); + metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, true); return result; } catch (Exception e) { - reportApiCallSuccess(executionParams, false); + metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, false); throw e; - } - } - - private void reportApiCallSuccess(ClientExecutionParams executionParams, boolean value) { - MetricCollector metricCollector = executionParams.getMetricCollector(); - if (metricCollector != null) { - metricCollector.reportMetric(CoreMetric.API_CALL_SUCCESSFUL, value); + } finally { + metricCollector.reportMetric(CoreMetric.API_CALL_DURATION, Duration.ofNanos(System.nanoTime() - callStart)); } } diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonAsyncHttpClient.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonAsyncHttpClient.java index 5772db0555a3..049d1cc64d85 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonAsyncHttpClient.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonAsyncHttpClient.java @@ -33,7 +33,6 @@ import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyTransactionIdStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyUserAgentStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallAttemptMetricCollectionStage; -import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallMetricCollectionStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncApiCallTimeoutTrackingStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncBeforeTransmissionExecutionInterceptorsStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncExecutionFailureExceptionReportingStage; @@ -214,8 +213,8 @@ public CompletableFuture execute( .then(async(() -> new UnwrapResponseContainer<>())) .then(async(() -> new AfterExecutionInterceptorsStage<>())) .wrappedWith(AsyncExecutionFailureExceptionReportingStage::new) - .wrappedWith(AsyncApiCallTimeoutTrackingStage::new) - .wrappedWith(AsyncApiCallMetricCollectionStage::new)::build)::build) + // Note: API_CALL_DURATION is measured by BaseAsyncClientHandler + .wrappedWith(AsyncApiCallTimeoutTrackingStage::new)::build)::build) .build(httpClientDependencies) .execute(request, createRequestExecutionDependencies()); } catch (RuntimeException e) { diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonSyncHttpClient.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonSyncHttpClient.java index 1996766372a4..53fc3c2e48a3 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonSyncHttpClient.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/AmazonSyncHttpClient.java @@ -30,7 +30,6 @@ import software.amazon.awssdk.core.internal.http.pipeline.stages.AfterTransmissionExecutionInterceptorsStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage; -import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyTransactionIdStage; import software.amazon.awssdk.core.internal.http.pipeline.stages.ApplyUserAgentStage; @@ -206,7 +205,7 @@ public OutputT execute(HttpResponseHandler> response .wrappedWith(RetryableStage::new)::build) .wrappedWith(StreamManagingStage::new) .wrappedWith(ApiCallTimeoutTrackingStage::new)::build) - .wrappedWith((deps, wrapped) -> new ApiCallMetricCollectionStage<>(wrapped)) + // Note: API_CALL_DURATION is measured by BaseSyncClientHandler .then(() -> new UnwrapResponseContainer<>()) .then(() -> new AfterExecutionInterceptorsStage<>()) .wrappedWith(ExecutionFailureExceptionReportingStage::new) diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/ApiCallMetricCollectionStage.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/ApiCallMetricCollectionStage.java deleted file mode 100644 index c7a6783fa7da..000000000000 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/ApiCallMetricCollectionStage.java +++ /dev/null @@ -1,62 +0,0 @@ -/* - * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. - * - * Licensed under the Apache License, Version 2.0 (the "License"). - * You may not use this file except in compliance with the License. - * A copy of the License is located at - * - * http://aws.amazon.com/apache2.0 - * - * or in the "license" file accompanying this file. This file is distributed - * on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either - * express or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -package software.amazon.awssdk.core.internal.http.pipeline.stages; - -import java.time.Duration; -import software.amazon.awssdk.annotations.SdkInternalApi; -import software.amazon.awssdk.core.Response; -import software.amazon.awssdk.core.internal.http.RequestExecutionContext; -import software.amazon.awssdk.core.internal.http.pipeline.RequestPipeline; -import software.amazon.awssdk.core.internal.http.pipeline.RequestToResponsePipeline; -import software.amazon.awssdk.core.internal.util.MetricUtils; -import software.amazon.awssdk.core.metrics.CoreMetric; -import software.amazon.awssdk.http.SdkHttpFullRequest; -import software.amazon.awssdk.metrics.MetricCollector; - -/** - * Wrapper pipeline that tracks the {@link CoreMetric#API_CALL_DURATION} metric. - */ -@SdkInternalApi -public class ApiCallMetricCollectionStage implements RequestToResponsePipeline { - private final RequestPipeline> wrapped; - - public ApiCallMetricCollectionStage(RequestPipeline> wrapped) { - this.wrapped = wrapped; - } - - @Override - public Response execute(SdkHttpFullRequest input, RequestExecutionContext context) throws Exception { - MetricCollector metricCollector = context.executionContext().metricCollector(); - - // Note: at this point, any exception, even a service exception, will - // be thrown from the wrapped pipeline so we can't use - // MetricUtil.measureDuration() - long callStart = System.nanoTime(); - try { - Response response = wrapped.execute(input, context); - return response; - } finally { - long d = System.nanoTime() - callStart; - metricCollector.reportMetric(CoreMetric.API_CALL_DURATION, Duration.ofNanos(d)); - // Collect SERVICE_ENDPOINT after pipeline execution so that EndpointResolutionStage - // has applied the resolved URL to the request. - SdkHttpFullRequest finalRequest = context.executionContext().interceptorContext().httpRequest() != null - ? (SdkHttpFullRequest) context.executionContext().interceptorContext().httpRequest() - : input; - MetricUtils.collectServiceEndpointMetrics(metricCollector, finalRequest); - } - } -} diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/AsyncApiCallMetricCollectionStage.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/AsyncApiCallMetricCollectionStage.java deleted file mode 100644 index e85a6f752aee..000000000000 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/http/pipeline/stages/AsyncApiCallMetricCollectionStage.java +++ /dev/null @@ -1,73 +0,0 @@ -/* - * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. - * - * Licensed under the Apache License, Version 2.0 (the "License"). - * You may not use this file except in compliance with the License. - * A copy of the License is located at - * - * http://aws.amazon.com/apache2.0 - * - * or in the "license" file accompanying this file. This file is distributed - * on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either - * express or implied. See the License for the specific language governing - * permissions and limitations under the License. - */ - -package software.amazon.awssdk.core.internal.http.pipeline.stages; - -import java.time.Duration; -import java.util.concurrent.CompletableFuture; -import software.amazon.awssdk.annotations.SdkInternalApi; -import software.amazon.awssdk.core.internal.http.RequestExecutionContext; -import software.amazon.awssdk.core.internal.http.pipeline.RequestPipeline; -import software.amazon.awssdk.core.internal.util.MetricUtils; -import software.amazon.awssdk.core.metrics.CoreMetric; -import software.amazon.awssdk.http.SdkHttpFullRequest; -import software.amazon.awssdk.metrics.MetricCollector; -import software.amazon.awssdk.utils.CompletableFutureUtils; - -/** - * Wrapper pipeline that tracks the {@link CoreMetric#API_CALL_DURATION} metric. - */ -@SdkInternalApi -public final class AsyncApiCallMetricCollectionStage implements RequestPipeline> { - private final RequestPipeline> wrapped; - - public AsyncApiCallMetricCollectionStage(RequestPipeline> wrapped) { - this.wrapped = wrapped; - } - - @Override - public CompletableFuture execute(SdkHttpFullRequest input, RequestExecutionContext context) throws Exception { - MetricCollector metricCollector = context.executionContext().metricCollector(); - - CompletableFuture future = new CompletableFuture<>(); - - long callStart = System.nanoTime(); - CompletableFuture executeFuture = wrapped.execute(input, context); - - executeFuture.whenComplete((r, t) -> { - long duration = System.nanoTime() - callStart; - metricCollector.reportMetric(CoreMetric.API_CALL_DURATION, Duration.ofNanos(duration)); - - // Collect SERVICE_ENDPOINT after pipeline execution so that EndpointResolutionStage - // has applied the resolved URL to the request. - SdkHttpFullRequest finalRequest = context.executionContext().interceptorContext().httpRequest() != null - ? (SdkHttpFullRequest) context.executionContext().interceptorContext().httpRequest() - : input; - MetricUtils.collectServiceEndpointMetrics(metricCollector, finalRequest); - - if (t != null) { - future.completeExceptionally(t); - } else { - future.complete(r); - } - }).exceptionally(t -> { - future.completeExceptionally(t); - return null; - }); - - return CompletableFutureUtils.forwardExceptionTo(future, executeFuture); - } -} diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/util/MetricUtils.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/util/MetricUtils.java index 8849e3dbd78c..003d57e126c8 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/util/MetricUtils.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/internal/util/MetricUtils.java @@ -18,8 +18,6 @@ import static software.amazon.awssdk.core.http.HttpResponseHandler.X_AMZN_REQUEST_ID_HEADERS; import static software.amazon.awssdk.core.http.HttpResponseHandler.X_AMZ_ID_2_HEADER; -import java.net.URI; -import java.net.URISyntaxException; import java.time.Duration; import java.util.OptionalLong; import java.util.concurrent.Callable; @@ -27,7 +25,6 @@ import java.util.concurrent.atomic.AtomicLong; import java.util.function.Supplier; import software.amazon.awssdk.annotations.SdkProtectedApi; -import software.amazon.awssdk.core.exception.SdkClientException; import software.amazon.awssdk.core.interceptor.SdkInternalExecutionAttribute; import software.amazon.awssdk.core.internal.http.RequestExecutionContext; import software.amazon.awssdk.core.metrics.CoreMetric; @@ -38,6 +35,7 @@ import software.amazon.awssdk.metrics.NoOpMetricCollector; import software.amazon.awssdk.metrics.SdkMetric; import software.amazon.awssdk.utils.Pair; +import software.amazon.awssdk.utils.http.SdkHttpUtils; import software.amazon.awssdk.utils.uri.SdkUri; /** @@ -107,19 +105,17 @@ public static Pair measureDurationUnsafe(Callable c, long st /** * Collect the SERVICE_ENDPOINT metric for this request. + * + *

Only the scheme, host and non-default port are used, so the endpoint string is assembled from the request's + * components directly reducing un-cached URI creations. */ public static void collectServiceEndpointMetrics(MetricCollector metricCollector, SdkHttpFullRequest httpRequest) { if (metricCollector != null && !(metricCollector instanceof NoOpMetricCollector) && httpRequest != null) { - // Only interested in the service endpoint so don't include any path, query, or fragment component - URI requestUri = httpRequest.getUri(); - try { - URI serviceEndpoint = SdkUri.getInstance().newUri( - requestUri.getScheme(), requestUri.getAuthority(), null, null, null); - metricCollector.reportMetric(CoreMetric.SERVICE_ENDPOINT, serviceEndpoint); - } catch (URISyntaxException e) { - // This should not happen since getUri() should return a valid URI - throw SdkClientException.create("Unable to collect SERVICE_ENDPOINT metric", e); - } + String protocol = httpRequest.protocol(); + int port = httpRequest.port(); + String portSuffix = SdkHttpUtils.isUsingStandardPort(protocol, port) ? "" : ":" + port; + metricCollector.reportMetric(CoreMetric.SERVICE_ENDPOINT, + SdkUri.getInstance().create(protocol + "://" + httpRequest.host() + portSuffix)); } } diff --git a/core/sdk-core/src/main/java/software/amazon/awssdk/core/metrics/CoreMetric.java b/core/sdk-core/src/main/java/software/amazon/awssdk/core/metrics/CoreMetric.java index d29274e28fa7..60939d869dd5 100644 --- a/core/sdk-core/src/main/java/software/amazon/awssdk/core/metrics/CoreMetric.java +++ b/core/sdk-core/src/main/java/software/amazon/awssdk/core/metrics/CoreMetric.java @@ -60,10 +60,22 @@ public final class CoreMetric { metric("ServiceEndpoint", URI.class, MetricLevel.ERROR); /** - * The duration of the API call. This includes all call attempts made. + * The duration of the API call. This includes all call attempts made and all interceptors. * - *

{@code API_CALL_DURATION ~= CREDENTIALS_FETCH_DURATION + MARSHALLING_DURATION + SUM_ALL(BACKOFF_DELAY_DURATION) + - * SUM_ALL(SIGNING_DURATION) + SUM_ALL(SERVICE_CALL_DURATION) + SUM_ALL(UNMARSHALLING_DURATION)} + *

For an asynchronous client the measurement ends when the returned + * {@link java.util.concurrent.CompletableFuture} completes, which for a streaming operation is when the response + * transformer completes. + * + *

{@code API_CALL_DURATION ~= CREDENTIALS_FETCH_DURATION + MARSHALLING_DURATION + ENDPOINT_RESOLVE_DURATION + + * SUM_ALL(BACKOFF_DELAY_DURATION) + SUM_ALL(SIGNING_DURATION) + SUM_ALL(SERVICE_CALL_DURATION) + + * SUM_ALL(UNMARSHALLING_DURATION)} + * + *

The relation is approximate because several steps inside the window have no metric of their own including + * request compression and checksum computation. + * + *

This is not bounded by a configured + * {@link software.amazon.awssdk.core.client.config.ClientOverrideConfiguration.Builder#apiCallTimeout(Duration) + * apiCallTimeout}, which covers a narrower window that excludes marshalling and the interceptors. */ public static final SdkMetric API_CALL_DURATION = metric("ApiCallDuration", Duration.class, MetricLevel.INFO); diff --git a/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/AsyncClientMetricCollectorExceptionTest.java b/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/AsyncClientMetricCollectorExceptionTest.java index 52de25b3063f..1362230e5aaa 100644 --- a/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/AsyncClientMetricCollectorExceptionTest.java +++ b/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/AsyncClientMetricCollectorExceptionTest.java @@ -23,7 +23,6 @@ import static software.amazon.awssdk.core.internal.util.AsyncResponseHandlerTestUtils.noOpResponseHandler; import static utils.HttpTestUtils.testAsyncClientBuilder; -import java.time.Duration; import java.util.Collections; import java.util.concurrent.CompletableFuture; import java.util.concurrent.TimeUnit; @@ -41,8 +40,8 @@ import software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain; import software.amazon.awssdk.core.interceptor.InterceptorContext; import software.amazon.awssdk.core.internal.http.AmazonAsyncHttpClient; -import software.amazon.awssdk.core.metrics.CoreMetric; import software.amazon.awssdk.core.protocol.VoidSdkResponse; +import software.amazon.awssdk.http.HttpMetric; import software.amazon.awssdk.http.SdkHttpFullRequest; import software.amazon.awssdk.http.SdkHttpFullResponse; import software.amazon.awssdk.http.SdkHttpResponse; @@ -70,11 +69,16 @@ public class AsyncClientMetricCollectorExceptionTest { @Mock private SdkAsyncHttpClient asyncHttpClient; + /** + * This exercises the request pipeline directly rather than going through {@code BaseAsyncClientHandler}, so it + * throws from a metric that the pipeline itself reports. {@code API_CALL_DURATION} is reported by the client handler, + * above the pipeline, so it is not reachable from here. + */ @Test public void exceptionInReportMetricReportedInFuture() { when(metricCollector.createChild(any())).thenReturn(metricCollector); Exception exception = new RuntimeException(MESSAGE); - doThrow(exception).when(metricCollector).reportMetric(eq(CoreMetric.API_CALL_DURATION), any(Duration.class)); + doThrow(exception).when(metricCollector).reportMetric(eq(HttpMetric.HTTP_STATUS_CODE), any(Integer.class)); CompletableFuture responseFuture = makeRequest(); diff --git a/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/handler/AsyncClientHandlerTest.java b/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/handler/AsyncClientHandlerTest.java index 2d4af1aedf9c..ae11cc3c2256 100644 --- a/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/handler/AsyncClientHandlerTest.java +++ b/core/sdk-core/src/test/java/software/amazon/awssdk/core/client/handler/AsyncClientHandlerTest.java @@ -18,10 +18,13 @@ import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatThrownBy; import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doThrow; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.verifyNoMoreInteractions; import static org.mockito.Mockito.when; +import java.time.Duration; import java.util.Arrays; import java.util.HashMap; import java.util.List; @@ -43,6 +46,7 @@ import software.amazon.awssdk.core.client.config.SdkClientOption; import software.amazon.awssdk.core.exception.SdkServiceException; import software.amazon.awssdk.core.http.HttpResponseHandler; +import software.amazon.awssdk.core.metrics.CoreMetric; import software.amazon.awssdk.core.protocol.VoidSdkResponse; import software.amazon.awssdk.core.retry.RetryPolicy; import software.amazon.awssdk.core.runtime.transform.Marshaller; @@ -51,6 +55,7 @@ import software.amazon.awssdk.http.async.AsyncExecuteRequest; import software.amazon.awssdk.http.async.SdkAsyncHttpClient; import software.amazon.awssdk.http.async.SdkAsyncHttpResponseHandler; +import software.amazon.awssdk.metrics.MetricCollector; import software.amazon.awssdk.retries.DefaultRetryStrategy; import utils.HttpTestUtils; import utils.ValidSdkObjects; @@ -110,6 +115,36 @@ public void successfulExecutionCallsResponseHandler() throws Exception { assertThat(actualResponse.sdkHttpResponse().headers()).isEqualTo(headers); } + /** + * The handler reports {@code API_CALL_DURATION} and {@code API_CALL_SUCCESSFUL} from a {@code whenComplete} action on + * the future it returns, so a collector that throws must fail that future rather than be swallowed. + * + *

Only assertable on the success path. When the source future has already failed and the {@code whenComplete} + * action throws, {@link CompletableFuture} keeps the source exception and discards the action's. The pipeline stage + * this reporting replaced behaved the same way, so that is a pre-existing limitation rather than a new one. + */ + @Test + public void metricCollectorThrowsOnSuccessfulExecution_exceptionReportedInFuture() throws Exception { + MetricCollector metricCollector = mock(MetricCollector.class); + when(metricCollector.createChild(any())).thenReturn(metricCollector); + RuntimeException exception = new RuntimeException("metric collector boom"); + doThrow(exception).when(metricCollector).reportMetric(eq(CoreMetric.API_CALL_DURATION), any(Duration.class)); + + ArgumentCaptor executeRequest = ArgumentCaptor.forClass(AsyncExecuteRequest.class); + + expectRetrievalFromMocks(); + when(httpClient.execute(executeRequest.capture())).thenReturn(httpClientFuture); + when(responseHandler.handle(any(), any())).thenReturn(VoidSdkResponse.builder().build()); + + CompletableFuture responseFuture = + asyncClientHandler.execute(clientExecutionParams().withMetricCollector(metricCollector)); + SdkAsyncHttpResponseHandler capturedHandler = executeRequest.getValue().responseHandler(); + capturedHandler.onHeaders(SdkHttpFullResponse.builder().statusCode(200).build()); + capturedHandler.onStream(new EmptyPublisher<>()); + + assertThatThrownBy(() -> responseFuture.get(1, TimeUnit.SECONDS)).hasRootCause(exception); + } + @Test public void failedExecutionCallsErrorResponseHandler() throws Exception { SdkServiceException exception = SdkServiceException.builder().message("Uh oh!").statusCode(500).build(); diff --git a/core/sdk-core/src/test/java/software/amazon/awssdk/core/internal/util/MetricUtilsTest.java b/core/sdk-core/src/test/java/software/amazon/awssdk/core/internal/util/MetricUtilsTest.java index 1a150620e87e..0c76993312c1 100644 --- a/core/sdk-core/src/test/java/software/amazon/awssdk/core/internal/util/MetricUtilsTest.java +++ b/core/sdk-core/src/test/java/software/amazon/awssdk/core/internal/util/MetricUtilsTest.java @@ -19,8 +19,10 @@ import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.verifyNoMoreInteractions; import java.io.IOException; +import java.net.URI; import java.time.Duration; import java.util.concurrent.CompletableFuture; import java.util.concurrent.CompletionException; @@ -31,8 +33,11 @@ import software.amazon.awssdk.core.http.HttpResponseHandler; import software.amazon.awssdk.core.metrics.CoreMetric; import software.amazon.awssdk.http.HttpMetric; +import software.amazon.awssdk.http.SdkHttpFullRequest; import software.amazon.awssdk.http.SdkHttpFullResponse; +import software.amazon.awssdk.http.SdkHttpMethod; import software.amazon.awssdk.metrics.MetricCollector; +import software.amazon.awssdk.metrics.NoOpMetricCollector; import software.amazon.awssdk.metrics.SdkMetric; import software.amazon.awssdk.utils.Pair; @@ -170,6 +175,113 @@ public void reportDuration_completableFuture_doesNotWrapException() { } } + @Test + public void collectServiceEndpointMetrics_when_standardHttpPort_omitsPort() { + MetricCollector mockCollector = mock(MetricCollector.class); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, requestBuilder("http", "example.amazonaws.com", 80).build()); + + verify(mockCollector).reportMetric(CoreMetric.SERVICE_ENDPOINT, URI.create("http://example.amazonaws.com")); + } + + @Test + public void collectServiceEndpointMetrics_when_standardHttpsPort_omitsPort() { + MetricCollector mockCollector = mock(MetricCollector.class); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, requestBuilder("https", "example.amazonaws.com", 443).build()); + + verify(mockCollector).reportMetric(CoreMetric.SERVICE_ENDPOINT, URI.create("https://example.amazonaws.com")); + } + + @Test + public void collectServiceEndpointMetrics_when_nonStandardPort_retainsPort() { + MetricCollector mockCollector = mock(MetricCollector.class); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, requestBuilder("http", "localhost", 8080).build()); + + verify(mockCollector).reportMetric(CoreMetric.SERVICE_ENDPOINT, URI.create("http://localhost:8080")); + } + + @Test + public void collectServiceEndpointMetrics_when_ipv6LiteralHost_reportsBracketedHost() { + MetricCollector mockCollector = mock(MetricCollector.class); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, requestBuilder("https", "[::1]", 8443).build()); + + verify(mockCollector).reportMetric(CoreMetric.SERVICE_ENDPOINT, URI.create("https://[::1]:8443")); + } + + @Test + public void collectServiceEndpointMetrics_when_requestHasPathAndQuery_reportsEndpointOnly() { + MetricCollector mockCollector = mock(MetricCollector.class); + + SdkHttpFullRequest request = requestBuilder("https", "example.amazonaws.com", 443) + .encodedPath("/some/resource/path") + .putRawQueryParameter("marker", "abc123") + .putRawQueryParameter("limit", "10") + .build(); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, request); + + verify(mockCollector).reportMetric(CoreMetric.SERVICE_ENDPOINT, URI.create("https://example.amazonaws.com")); + } + + @Test + public void collectServiceEndpointMetrics_when_accountIdHost_reportsEndpointOnly() { + MetricCollector mockCollector = mock(MetricCollector.class); + + // Account-id hosts route through the SdkUri cache. Assert the cached value is still the endpoint alone. + SdkHttpFullRequest request = requestBuilder("https", "123456789012.ddb.us-east-1.amazonaws.com", 443) + .encodedPath("/") + .build(); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, request); + + verify(mockCollector).reportMetric(CoreMetric.SERVICE_ENDPOINT, + URI.create("https://123456789012.ddb.us-east-1.amazonaws.com")); + } + + @Test + public void collectServiceEndpointMetrics_when_nullCollector_doesNothing() { + // A host that cannot be parsed proves the guard short-circuits before the URI is built. + MetricUtils.collectServiceEndpointMetrics(null, requestBuilder("http", "in valid host", 80).build()); + } + + @Test + public void collectServiceEndpointMetrics_when_noOpCollector_doesNothing() { + MetricUtils.collectServiceEndpointMetrics(NoOpMetricCollector.create(), + requestBuilder("http", "in valid host", 80).build()); + } + + @Test + public void collectServiceEndpointMetrics_when_nullRequest_doesNothing() { + MetricCollector mockCollector = mock(MetricCollector.class); + + MetricUtils.collectServiceEndpointMetrics(mockCollector, null); + + verifyNoMoreInteractions(mockCollector); + } + + @Test + public void collectServiceEndpointMetrics_when_hostIsUnparseable_throwsIllegalArgumentException() { + MetricCollector mockCollector = mock(MetricCollector.class); + SdkHttpFullRequest request = requestBuilder("http", "in valid host", 80).build(); + + // Documents the existing contract: an unparseable endpoint surfaces the IllegalArgumentException from URI + // parsing. The previous implementation reached the same outcome, because SdkHttpRequest#getUri() threw this + // before its URISyntaxException handler could run. + thrown.expect(IllegalArgumentException.class); + MetricUtils.collectServiceEndpointMetrics(mockCollector, request); + } + + private static SdkHttpFullRequest.Builder requestBuilder(String protocol, String host, int port) { + return SdkHttpFullRequest.builder() + .method(SdkHttpMethod.POST) + .protocol(protocol) + .host(host) + .port(port); + } + @Test public void collectHttpMetrics_collectsAllExpectedMetrics() { MetricCollector mockCollector = mock(MetricCollector.class); diff --git a/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/ApiCallDurationAssertions.java b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/ApiCallDurationAssertions.java new file mode 100644 index 000000000000..723ff24017fd --- /dev/null +++ b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/ApiCallDurationAssertions.java @@ -0,0 +1,126 @@ +/* + * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"). + * You may not use this file except in compliance with the License. + * A copy of the License is located at + * + * http://aws.amazon.com/apache2.0 + * + * or in the "license" file accompanying this file. This file is distributed + * on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either + * express or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ + +package software.amazon.awssdk.services.metrics; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.time.Duration; +import java.util.List; +import software.amazon.awssdk.core.metrics.CoreMetric; +import software.amazon.awssdk.metrics.MetricCollection; +import software.amazon.awssdk.metrics.SdkMetric; + +/** + * Assertions on the window that {@link CoreMetric#API_CALL_DURATION} is supposed to cover. + */ +public final class ApiCallDurationAssertions { + + private ApiCallDurationAssertions() { + } + + /** + * Assert that {@code ApiCallDuration} individually encloses each duration reported inside its window. + * + *

Every one of these is a necessary condition on its own, so this is safe to apply to any API call, including + * calls that failed or were retried. + * + *

{@code MARSHALLING_DURATION} and {@code ENDPOINT_RESOLVE_DURATION} are additionally required to be present. An + * enclosure check over an absent metric passes vacuously, which would let a regression that stopped reporting one of + * them through unnoticed — and those two are exactly the ones this PR's defect hid. + */ + public static void assertEnclosesComponents(MetricCollection apiCall) { + Duration apiCallDuration = single(apiCall, CoreMetric.API_CALL_DURATION); + + // Required: every API call marshals a request and resolves an endpoint before it can be sent, so a regression + // that stops reporting either of these must fail rather than pass vacuously. + assertRequiredAndEnclosed(apiCallDuration, apiCall, CoreMetric.MARSHALLING_DURATION); + assertRequiredAndEnclosed(apiCallDuration, apiCall, CoreMetric.ENDPOINT_RESOLVE_DURATION); + + // Optional: absent when the endpoint is not signed, when an identity is already cached in a form that reports no + // duration, or when the call failed before the phase ran. + assertEnclosedIfPresent(apiCallDuration, apiCall, CoreMetric.CREDENTIALS_FETCH_DURATION); + + for (MetricCollection attempt : apiCall.children()) { + assertEnclosedIfPresent(apiCallDuration, attempt, CoreMetric.SIGNING_DURATION); + assertEnclosedIfPresent(apiCallDuration, attempt, CoreMetric.SERVICE_CALL_DURATION); + assertEnclosedIfPresent(apiCallDuration, attempt, CoreMetric.UNMARSHALLING_DURATION); + } + } + + /** + * Assert the javadoc additivity formula: {@code ApiCallDuration} is at least the sum of the components it is + * documented to be composed of. + * + *

The relation is an inequality rather than an equality because several steps inside the window have no metric of + * its own. + * + *

Only apply this where the phases are genuinely disjoint: a single-attempt call on a synchronous client. It does + * not hold on asynchronous clients, where {@code SERVICE_CALL_DURATION} does not stop at time to first byte (see + * {@code CoreMetric.TIME_TO_FIRST_BYTE}) and so overlaps {@code UNMARSHALLING_DURATION} for streaming operations. + * Use {@link #assertEnclosesComponents(MetricCollection)} there, which holds unconditionally. + */ + public static void assertEnclosesComponentSum(MetricCollection apiCall) { + Duration apiCallDuration = single(apiCall, CoreMetric.API_CALL_DURATION); + + Duration componentSum = sum(apiCall, CoreMetric.MARSHALLING_DURATION) + .plus(sum(apiCall, CoreMetric.ENDPOINT_RESOLVE_DURATION)) + .plus(sum(apiCall, CoreMetric.CREDENTIALS_FETCH_DURATION)); + + for (MetricCollection attempt : apiCall.children()) { + componentSum = componentSum.plus(sum(attempt, CoreMetric.BACKOFF_DELAY_DURATION)) + .plus(sum(attempt, CoreMetric.SIGNING_DURATION)) + .plus(sum(attempt, CoreMetric.SERVICE_CALL_DURATION)) + .plus(sum(attempt, CoreMetric.UNMARSHALLING_DURATION)); + } + + assertThat(apiCallDuration) + .as("ApiCallDuration must be at least the sum of the components") + .isGreaterThanOrEqualTo(componentSum); + } + + private static void assertRequiredAndEnclosed(Duration apiCallDuration, + MetricCollection collection, + SdkMetric metric) { + assertThat(collection.metricValues(metric)) + .as("%s must be reported for every API call", metric.name()) + .isNotEmpty(); + assertEnclosedIfPresent(apiCallDuration, collection, metric); + } + + private static void assertEnclosedIfPresent(Duration apiCallDuration, + MetricCollection collection, + SdkMetric metric) { + for (Duration value : collection.metricValues(metric)) { + assertThat(apiCallDuration) + .as("ApiCallDuration must enclose %s", metric.name()) + .isGreaterThanOrEqualTo(value); + } + } + + private static Duration single(MetricCollection collection, SdkMetric metric) { + List values = collection.metricValues(metric); + assertThat(values).as("%s must be reported", metric.name()).hasSize(1); + return values.get(0); + } + + private static Duration sum(MetricCollection collection, SdkMetric metric) { + Duration total = Duration.ZERO; + for (Duration value : collection.metricValues(metric)) { + total = total.plus(value); + } + return total; + } +} diff --git a/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/ApiCallDurationWindowTest.java b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/ApiCallDurationWindowTest.java new file mode 100644 index 000000000000..36e6c0b67d1e --- /dev/null +++ b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/ApiCallDurationWindowTest.java @@ -0,0 +1,312 @@ +/* + * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"). + * You may not use this file except in compliance with the License. + * A copy of the License is located at + * + * http://aws.amazon.com/apache2.0 + * + * or in the "license" file accompanying this file. This file is distributed + * on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either + * express or implied. See the License for the specific language governing + * permissions and limitations under the License. + */ + +package software.amazon.awssdk.services.metrics; + +import static com.github.tomakehurst.wiremock.client.WireMock.aResponse; +import static com.github.tomakehurst.wiremock.client.WireMock.anyUrl; +import static com.github.tomakehurst.wiremock.client.WireMock.post; +import static com.github.tomakehurst.wiremock.client.WireMock.stubFor; +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; + +import com.github.tomakehurst.wiremock.junit.WireMockRule; +import java.net.URI; +import java.nio.ByteBuffer; +import java.time.Duration; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.TimeUnit; +import java.util.function.Consumer; +import org.junit.After; +import org.junit.Before; +import org.junit.Rule; +import org.junit.Test; +import org.mockito.ArgumentCaptor; +import org.reactivestreams.Subscriber; +import org.reactivestreams.Subscription; +import software.amazon.awssdk.core.async.AsyncResponseTransformer; +import software.amazon.awssdk.core.async.SdkPublisher; +import software.amazon.awssdk.core.client.config.ClientOverrideConfiguration; +import software.amazon.awssdk.core.interceptor.Context; +import software.amazon.awssdk.core.interceptor.ExecutionAttributes; +import software.amazon.awssdk.core.interceptor.ExecutionInterceptor; +import software.amazon.awssdk.core.metrics.CoreMetric; +import software.amazon.awssdk.endpoints.Endpoint; +import software.amazon.awssdk.metrics.MetricCollection; +import software.amazon.awssdk.metrics.MetricPublisher; +import software.amazon.awssdk.regions.Region; +import software.amazon.awssdk.services.protocolrestjson.ProtocolRestJsonAsyncClient; +import software.amazon.awssdk.services.protocolrestjson.ProtocolRestJsonAsyncClientBuilder; +import software.amazon.awssdk.services.protocolrestjson.ProtocolRestJsonClient; +import software.amazon.awssdk.services.protocolrestjson.ProtocolRestJsonClientBuilder; +import software.amazon.awssdk.services.protocolrestjson.endpoints.ProtocolRestJsonEndpointParams; +import software.amazon.awssdk.services.protocolrestjson.endpoints.ProtocolRestJsonEndpointProvider; +import software.amazon.awssdk.services.protocolrestjson.model.StreamingOutputOperationResponse; +import software.amazon.awssdk.services.testutil.MockIdentityProviderUtil; + +/** + * Verifies which phases of an API call fall inside the {@link CoreMetric#API_CALL_DURATION} window, for both the + * synchronous and asynchronous clients. + * + *

Each test injects a delay that is large relative to everything else the call does, into exactly one phase, and then + * asserts that the delay is visible in the reported {@code ApiCallDuration}. A phase that is outside the measured window + * contributes nothing to it, so the assertion fails outright rather than by a margin. This is deliberately stronger than + * checking the additivity formula: the phases at issue normally cost microseconds against a call that costs + * milliseconds, so an inequality over real timings passes whether or not they are included. + * + *

The phases covered are work before marshalling, endpoint resolution, the {@code afterExecution} interceptors, and + * completion of an {@link AsyncResponseTransformer}. The first three are places the window has been wrong, on one or both + * clients. The last is not a past defect but is the documented end of the asynchronous window for streaming operations. + */ +public class ApiCallDurationWindowTest { + + /** + * Large enough to dwarf the rest of the call and to survive scheduling jitter, small enough to keep the test quick. + */ + private static final Duration INJECTED_DELAY = Duration.ofMillis(300); + + @Rule + public WireMockRule wireMock = new WireMockRule(0); + + private MetricPublisher publisher; + private ScheduledExecutorService scheduler; + + @Before + public void setup() { + publisher = mock(MetricPublisher.class); + scheduler = Executors.newSingleThreadScheduledExecutor(); + stubFor(post(anyUrl()).willReturn(aResponse().withStatus(200) + .withHeader("x-amz-request-id", "req-id") + .withBody("{}"))); + } + + @After + public void teardown() { + scheduler.shutdownNow(); + } + + @Test + public void syncClient_apiCallDuration_includesWorkBeforeMarshalling() { + callSync(b -> b.addExecutionInterceptor(new DelayingInterceptor(Phase.BEFORE_MARSHALLING)), null); + assertDelayIsMeasured(); + } + + @Test + public void asyncClient_apiCallDuration_includesWorkBeforeMarshalling() { + callAsync(b -> b.addExecutionInterceptor(new DelayingInterceptor(Phase.BEFORE_MARSHALLING)), null); + assertDelayIsMeasured(); + } + + @Test + public void syncClient_apiCallDuration_includesEndpointResolution() { + callSync(b -> { + }, slowEndpointProvider()); + assertDelayIsMeasured(); + } + + @Test + public void asyncClient_apiCallDuration_includesEndpointResolution() { + callAsync(b -> { + }, slowEndpointProvider()); + assertDelayIsMeasured(); + } + + @Test + public void syncClient_apiCallDuration_includesAfterExecutionInterceptors() { + callSync(b -> b.addExecutionInterceptor(new DelayingInterceptor(Phase.AFTER_EXECUTION)), null); + assertDelayIsMeasured(); + } + + @Test + public void asyncClient_apiCallDuration_includesAfterExecutionInterceptors() { + callAsync(b -> b.addExecutionInterceptor(new DelayingInterceptor(Phase.AFTER_EXECUTION)), null); + assertDelayIsMeasured(); + } + + /** + * The async window closes when the future returned to the caller completes, which for a streaming operation is when + * the {@link AsyncResponseTransformer} completes. This delays only that completion — the transformer schedules it + * rather than blocking, so no pipeline stage and no event loop thread is held up. Anything the delay shows up in must + * therefore be measuring as far as the transformer. + */ + @Test + public void asyncClient_apiCallDuration_includesResponseTransformerCompletion() { + try (ProtocolRestJsonAsyncClient client = asyncClientBuilder(b -> { + }, null).build()) { + client.streamingOutputOperation(r -> { + }, new DelayedCompletionTransformer()).join(); + } + + assertDelayIsMeasured(); + } + + private void assertDelayIsMeasured() { + assertThat(capturedApiCallDuration()) + .as("ApiCallDuration must include the delay injected into the phase under test") + .isGreaterThanOrEqualTo(INJECTED_DELAY); + } + + private Duration capturedApiCallDuration() { + ArgumentCaptor captor = ArgumentCaptor.forClass(MetricCollection.class); + verify(publisher).publish(captor.capture()); + MetricCollection apiCall = captor.getValue(); + ApiCallDurationAssertions.assertEnclosesComponents(apiCall); + return apiCall.metricValues(CoreMetric.API_CALL_DURATION).get(0); + } + + private void callSync(Consumer overrides, + ProtocolRestJsonEndpointProvider endpointProvider) { + ProtocolRestJsonClientBuilder builder = + ProtocolRestJsonClient.builder() + .region(Region.US_WEST_2) + .credentialsProvider(MockIdentityProviderUtil.mockIdentityProvider()) + .endpointOverride(URI.create("http://localhost:" + wireMock.port())) + .overrideConfiguration(c -> { + c.addMetricPublisher(publisher).retryStrategy(b -> b.maxAttempts(1)); + overrides.accept(c); + }); + if (endpointProvider != null) { + builder.endpointProvider(endpointProvider); + } + try (ProtocolRestJsonClient client = builder.build()) { + client.allTypes(); + } + } + + private void callAsync(Consumer overrides, + ProtocolRestJsonEndpointProvider endpointProvider) { + try (ProtocolRestJsonAsyncClient client = asyncClientBuilder(overrides, endpointProvider).build()) { + client.allTypes().join(); + } + } + + private ProtocolRestJsonAsyncClientBuilder asyncClientBuilder( + Consumer overrides, + ProtocolRestJsonEndpointProvider endpointProvider) { + + ProtocolRestJsonAsyncClientBuilder builder = + ProtocolRestJsonAsyncClient.builder() + .region(Region.US_WEST_2) + .credentialsProvider(MockIdentityProviderUtil.mockIdentityProvider()) + .endpointOverride(URI.create("http://localhost:" + wireMock.port())) + .overrideConfiguration(c -> { + c.addMetricPublisher(publisher).retryStrategy(b -> b.maxAttempts(1)); + overrides.accept(c); + }); + if (endpointProvider != null) { + builder.endpointProvider(endpointProvider); + } + return builder; + } + + private ProtocolRestJsonEndpointProvider slowEndpointProvider() { + ProtocolRestJsonEndpointProvider delegate = ProtocolRestJsonEndpointProvider.defaultProvider(); + return new ProtocolRestJsonEndpointProvider() { + @Override + public CompletableFuture resolveEndpoint(ProtocolRestJsonEndpointParams endpointParams) { + sleep(); + return delegate.resolveEndpoint(endpointParams); + } + }; + } + + private static void sleep() { + try { + Thread.sleep(INJECTED_DELAY.toMillis()); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + throw new IllegalStateException(e); + } + } + + private enum Phase { + BEFORE_MARSHALLING, + AFTER_EXECUTION + } + + /** + * Drains the response body, then completes its future {@link #INJECTED_DELAY} later via the scheduler rather than by + * sleeping, so the delay is purely in the transformer's completion and not in any thread the SDK owns. + */ + private final class DelayedCompletionTransformer + implements AsyncResponseTransformer { + + private volatile CompletableFuture result; + + @Override + public CompletableFuture prepare() { + result = new CompletableFuture<>(); + return result; + } + + @Override + public void onResponse(StreamingOutputOperationResponse response) { + } + + @Override + public void onStream(SdkPublisher publisher) { + publisher.subscribe(new Subscriber() { + @Override + public void onSubscribe(Subscription subscription) { + subscription.request(Long.MAX_VALUE); + } + + @Override + public void onNext(ByteBuffer byteBuffer) { + } + + @Override + public void onError(Throwable throwable) { + result.completeExceptionally(throwable); + } + + @Override + public void onComplete() { + scheduler.schedule(() -> result.complete(null), INJECTED_DELAY.toMillis(), TimeUnit.MILLISECONDS); + } + }); + } + + @Override + public void exceptionOccurred(Throwable error) { + result.completeExceptionally(error); + } + } + + private static final class DelayingInterceptor implements ExecutionInterceptor { + private final Phase phase; + + private DelayingInterceptor(Phase phase) { + this.phase = phase; + } + + @Override + public void beforeMarshalling(Context.BeforeMarshalling context, ExecutionAttributes executionAttributes) { + if (phase == Phase.BEFORE_MARSHALLING) { + sleep(); + } + } + + @Override + public void afterExecution(Context.AfterExecution context, ExecutionAttributes executionAttributes) { + if (phase == Phase.AFTER_EXECUTION) { + sleep(); + } + } + } +} diff --git a/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/CoreMetricsTest.java b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/CoreMetricsTest.java index c1ec12515ca0..f25d137beab8 100644 --- a/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/CoreMetricsTest.java +++ b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/CoreMetricsTest.java @@ -212,6 +212,21 @@ public void testApiCall_operationSuccessful_addsMetrics() { .isGreaterThanOrEqualTo(Duration.ZERO); } + @Test + public void testApiCall_operationSuccessful_apiCallDurationEnclosesItsComponents() { + client.allTypes(); + + ArgumentCaptor collectionCaptor = ArgumentCaptor.forClass(MetricCollection.class); + verify(mockPublisher).publish(collectionCaptor.capture()); + + MetricCollection capturedCollection = collectionCaptor.getValue(); + + ApiCallDurationAssertions.assertEnclosesComponents(capturedCollection); + ApiCallDurationAssertions.assertEnclosesComponentSum(capturedCollection); + } + + + @Test public void testApiCall_serviceReturnsError_errorInfoIncludedInMetrics() throws IOException { AbortableInputStream content = contentStream("{}"); @@ -244,6 +259,7 @@ public void testApiCall_serviceReturnsError_errorInfoIncludedInMetrics() throws assertThat(capturedCollection.children()).hasSize(MAX_ATTEMPTS); assertThat(capturedCollection.metricValues(CoreMetric.RETRY_COUNT)).containsExactly(MAX_RETRIES); assertThat(capturedCollection.metricValues(CoreMetric.API_CALL_SUCCESSFUL)).containsExactly(false); + ApiCallDurationAssertions.assertEnclosesComponents(capturedCollection); for (MetricCollection requestMetrics : capturedCollection.children()) { // A service exception is still a successful HTTP execution so diff --git a/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/async/BaseAsyncCoreMetricsTest.java b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/async/BaseAsyncCoreMetricsTest.java index 851da2a007dd..628507255e36 100644 --- a/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/async/BaseAsyncCoreMetricsTest.java +++ b/test/codegen-generated-classes-test/src/test/java/software/amazon/awssdk/services/metrics/async/BaseAsyncCoreMetricsTest.java @@ -44,6 +44,7 @@ import software.amazon.awssdk.http.HttpMetric; import software.amazon.awssdk.metrics.MetricCollection; import software.amazon.awssdk.metrics.MetricPublisher; +import software.amazon.awssdk.services.metrics.ApiCallDurationAssertions; import software.amazon.awssdk.services.protocolrestjson.model.EmptyModeledException; @RunWith(MockitoJUnitRunner.class) @@ -268,6 +269,11 @@ private void verifySuccessfulApiCallCollection(MetricCollection capturedCollecti verifyApiCallCollection(capturedCollection); assertThat(capturedCollection.metricValues(CoreMetric.RETRY_COUNT)).containsExactly(0); assertThat(capturedCollection.metricValues(CoreMetric.API_CALL_SUCCESSFUL)).containsExactly(true); + // Note: the javadoc additivity formula is deliberately not asserted as a whole here, only per component in + // verifyApiCallCollection. On async the phases are not disjoint: SERVICE_CALL_DURATION does not stop at time to + // first byte, as noted on CoreMetric.TIME_TO_FIRST_BYTE, so for a streaming operation it overlaps + // UNMARSHALLING_DURATION and their sum can marginally exceed ApiCallDuration. That is a separate defect in + // SERVICE_CALL_DURATION, not in the window measured here. } private void verifyApiCallCollection(MetricCollection capturedCollection) { @@ -284,6 +290,9 @@ private void verifyApiCallCollection(MetricCollection capturedCollection) { .isGreaterThan(FIXED_DELAY); assertThat(capturedCollection.metricValues(CoreMetric.SERVICE_ENDPOINT).get(0)).toString() .startsWith("http://localhost"); + // The async client used to measure ApiCallDuration from the signing stage onwards, which excluded marshalling + // and endpoint resolution. Guard against that regression, and against the two clients diverging again. + ApiCallDurationAssertions.assertEnclosesComponents(capturedCollection); } void stubSuccessfulResponse() {