aws-sdk-java-v2 icon indicating copy to clipboard operation
aws-sdk-java-v2 copied to clipboard

Published 20 hours ago • verified publisher icon aws

NullPointer and socketTimeout on reads/writes to S3

Open espen-grodem opened this issue 2 years ago • 4 comments

Describe the bug

After upgrading to AWS SDK for Java 2.x, we have occasionally gotten Socket closed exceptions when writing to S3. The error not on every write but quite often.

To deal with the Socket closed exceptions I made the following changes to the S3 client:

Increased apiCallAttermptTimeout to from 500 ms to 600 ms Defined apiCallTimeout to 6 seconds This resulted in nullPointerExceptions occasionally when reading from S3. The error is thrown from HttpURLConnection

Update I have created this discussion but have not been followed up there.

We are now also experiencing nullPointers on reads from S3 with the changes above reverted. The nullPointer is thrown from http.HttpURLConnection

Expected Behavior

Regular reads and writes to S3 without exceptions. The increase of apiCallAttermptTimeout and definition of apiCallTimeout, causing a null pointer is also confusing and not expected behaviour.

Current Behavior

Stacktrace for Socket closed

java.io.UncheckedIOException: java.net.SocketException: Socket closed
--
at software.amazon.awssdk.utils.FunctionalUtils.asRuntimeException(FunctionalUtils.java:180)
at software.amazon.awssdk.utils.FunctionalUtils.lambda$safeSupplier$4(FunctionalUtils.java:110)
at software.amazon.awssdk.utils.FunctionalUtils.invokeSafely(FunctionalUtils.java:136)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.lambda$tryGetOutputStream$0(UrlConnectionHttpClient.java:324)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.getAndHandle100Bug(UrlConnectionHttpClient.java:360)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.tryGetOutputStream(UrlConnectionHttpClient.java:324)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.call(UrlConnectionHttpClient.java:301)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.call(UrlConnectionHttpClient.java:274)
at software.amazon.awssdk.core.internal.util.MetricUtils.measureDurationUnsafe(MetricUtils.java:67)
at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.executeHttpRequest(MakeHttpRequestStage.java:77)
at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.execute(MakeHttpRequestStage.java:56)
at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.execute(MakeHttpRequestStage.java:39)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:72)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:42)
at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:78)
at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:40)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:52)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:37)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:81)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:36)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:56)
at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:36)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.executeWithTimer(ApiCallTimeoutTrackingStage.java:80)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:60)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:42)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:50)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:32)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:37)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26)
at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:196)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:171)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:82)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:179)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:76)
at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45)
at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:56)
at software.amazon.awssdk.services.s3.DefaultS3Client.putObject(DefaultS3Client.java:8783)
at software.amazon.awssdk.services.s3.S3Client.putObject(S3Client.java:17277)
at com.visma.of.solverwrapper.aws.s3.S3Handler.putObject(S3Handler.java:84)
at com.visma.of.solverwrapper.aws.s3.S3Util.writeJsonObjectToS3Path(S3Util.java:34)
at com.visma.of.solverwrapper.aws.solver.RunSimpleSolverHandler.handleRequest(RunSimpleSolverHandler.java:62)
at com.visma.of.solverwrapper.aws.solver.RunSimpleSolverHandler.handleRequest(RunSimpleSolverHandler.java:25)
at lambdainternal.EventHandlerLoader$PojoHandlerAsStreamHandler.handleRequest(EventHandlerLoader.java:205)
at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:905)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:261)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:200)
at lambdainternal.AWSLambda.main(AWSLambda.java:194)
Caused by: java.net.SocketException: Socket closed
at java.base/java.net.SocketInputStream.read(Unknown Source)
at java.base/java.net.SocketInputStream.read(Unknown Source)
at java.base/sun.security.ssl.SSLSocketInputRecord.read(Unknown Source)
at java.base/sun.security.ssl.SSLSocketInputRecord.readHeader(Unknown Source)
at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(Unknown Source)
at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(Unknown Source)
at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(Unknown Source)
at java.base/java.io.BufferedInputStream.fill(Unknown Source)
at java.base/java.io.BufferedInputStream.read1(Unknown Source)
at java.base/java.io.BufferedInputStream.read(Unknown Source)
at java.base/sun.net.www.http.HttpClient.parseHTTPHeader(Unknown Source)
at java.base/sun.net.www.http.HttpClient.parseHTTP(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.expect100Continue(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream(Unknown Source)
at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(Unknown Source)
at software.amazon.awssdk.utils.FunctionalUtils.lambda$safeSupplier$4(FunctionalUtils.java:108)
... 53 more

Stacktrace for nullPointer

SEVERE: java.lang.NullPointerException
--
java.lang.RuntimeException: java.lang.NullPointerException
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getHeaderField(Unknown Source)
at java.base/java.net.HttpURLConnection.getResponseCode(Unknown Source)
at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(Unknown Source)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.getResponseCodeSafely(UrlConnectionHttpClient.java:424)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.call(UrlConnectionHttpClient.java:307)
at software.amazon.awssdk.http.urlconnection.UrlConnectionHttpClient$RequestCallable.call(UrlConnectionHttpClient.java:274)
at software.amazon.awssdk.core.internal.util.MetricUtils.measureDurationUnsafe(MetricUtils.java:67)
at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.executeHttpRequest(MakeHttpRequestStage.java:77)
at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.execute(MakeHttpRequestStage.java:56)
at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeHttpRequestStage.execute(MakeHttpRequestStage.java:39)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:72)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptTimeoutTrackingStage.execute(ApiCallAttemptTimeoutTrackingStage.java:42)
at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:78)
at software.amazon.awssdk.core.internal.http.pipeline.stages.TimeoutExceptionHandlingStage.execute(TimeoutExceptionHandlingStage.java:
```40)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:52)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallAttemptMetricCollectionStage.execute(ApiCallAttemptMetricCollectionStage.java:37)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:81)
at software.amazon.awssdk.core.internal.http.pipeline.stages.RetryableStage.execute(RetryableStage.java:36)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:56)
at software.amazon.awssdk.core.internal.http.StreamManagingStage.execute(StreamManagingStage.java:36)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.executeWithTimer(ApiCallTimeoutTrackingStage.java:80)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:60)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallTimeoutTrackingStage.execute(ApiCallTimeoutTrackingStage.java:42)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:50)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ApiCallMetricCollectionStage.execute(ApiCallMetricCollectionStage.java:32)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:37)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26)
at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:196)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:171)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$0(BaseSyncClientHandler.java:68)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:179)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:62)
at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:52)
at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:63)
at software.amazon.awssdk.services.s3.DefaultS3Client.getObject(DefaultS3Client.java:4483)
at software.amazon.awssdk.services.s3.S3Client.getObject(S3Client.java:7916)
at software.amazon.awssdk.services.s3.S3Client.getObject(S3Client.java:8161)
at com.visma.of.solverwrapper.aws.s3.S3Handler.getJsonObjectFromS3File(S3Handler.java:114)
at com.visma.of.solverwrapper.aws.s3.S3Handler.getJsonObjectFromS3FileWithRetries(S3Handler.java:94)
at com.visma.of.solverwrapper.validator.RequestValidator.runValidator(RequestValidator.java:34)
at com.visma.of.solverwrapper.aws.validator.RunValidatorHandler.handleRequest(RunValidatorHandler.java:39)
at com.visma.of.solverwrapper.aws.validator.RunValidatorHandler.handleRequest(RunValidatorHandler.java:19)
at lambdainternal.EventHandlerLoader$PojoHandlerAsStreamHandler.handleRequest(EventHandlerLoader.java:205)
at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:905)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:261)
at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:200)
at lambdainternal.AWSLambda.main(AWSLambda.java:194)
Caused by: java.lang.NullPointerException
at java.base/sun.net.www.protocol.http.HttpURLConnection.writeRequests(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(Unknown Source)
at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
... 54 more

Reproduction Steps

The client is defined in the following way:

private S3Client getS3Client(IConfiguration configuration) {
        ClientOverrideConfiguration clientOverrideConfiguration =
            ClientOverrideConfiguration.builder()
                .retryPolicy(
                    RetryPolicy.builder(RetryMode.ADAPTIVE)
                        .numRetries(3)
                        .build())
                .apiCallAttemptTimeout(Duration.ofMillis(500))
                .build();
        UrlConnectionHttpClient.Builder httpClientBuilder = UrlConnectionHttpClient.builder()
            .connectionTimeout(Duration.ofMillis(100));
        
return S3Client.builder()
            .httpClientBuilder(httpClientBuilder)
            .overrideConfiguration(clientOverrideConfiguration)
            .region(Region.of(configuration.getRegion()))
            .credentialsProvider(DefaultCredentialsProvider.create())
            .build();
    }

and the method for read and write to S3 as this:

public void putObject(String content, String name) {
        try {
            logger.info("Writing {} to S3.", name);
            s3.putObject(p -> p.bucket(bucketName).key(name), RequestBody.fromString(content));
        } catch (SdkClientException e) {
            throw new SolverWrapperException(e.getMessage(), e);
        }
    }


    public JSONObject getJsonObjectFromS3FileWithRetries(String name) {
        for (int retries = 0; retries < 3; retries++) {
            try {
                return getJsonObjectFromS3File(name);
            } catch (SolverWrapperException e) {
                logger.warn("Failed to get object from S3. Retrying...", e);
            }
            try {
                TimeUnit.SECONDS.sleep(1);
            } catch (InterruptedException e) {
                logger.error("Interrupted while waiting for retry.", e);
                Thread.currentThread().interrupt();
            }
        }
        throw new SolverWrapperException("Failed to get object from S3 after 3 retries.");
    }

    /**
     * Get an object from S3 as an JSONObject
     */
    public JSONObject getJsonObjectFromS3File(String name) {

        logger.info("Reading {} from S3.", name);
        GetObjectRequest request = GetObjectRequest.builder()
            .bucket(bucketName)
            .key(name)
            .build();

        try (ResponseInputStream<GetObjectResponse> object = s3.getObject(request)) {
            SdkBytes content = SdkBytes.fromInputStream(object);
            String objStr = content.asUtf8String();
            return JSON.parseStringToJsonAware(objStr, parser);
        } catch (IOException e) {
            throw new SolverWrapperException(e.getMessage(), e);
        }
    }

Possible Solution

Defining socketTimout in the httpClientBuilder could maybe contribute

Additional Information/Context

No response

AWS Java SDK version used

2.20.131

JDK version used

openjdk 11.0.16 2022-07-19 LTS OpenJDK Runtime Environment Corretto-11.0.16.8.1 (build 11.0.16+8-LTS) OpenJDK 64-Bit Server VM Corretto-11.0.16.8.1 (build 11.0.16+8-LTS, mixed mode)

Operating System and version

Mac Ventura 13.3.1 (a)

espen-grodem avatar Oct 03 '23 09:10 espen-grodem

@espen-grodem I'm sorry for losing track of the Discussion you created.

I'll discuss the next steps with the rest of the team, and will get back.

debora-ito avatar Oct 10 '23 22:10 debora-ito

We will investigate this further and find a root cause.

debora-ito avatar Oct 13 '23 00:10 debora-ito

@debora-ito What is the status of this issue?

espen-grodem avatar Nov 21 '23 12:11 espen-grodem

This is happening with the java.net.URL connection. What happens if you switch over to the apache httpclient?

steveloughran avatar Nov 25 '23 13:11 steveloughran