S3Exception when uploading - "The difference between the request time and the current time is too large"

[tom-smalls]

Describe the bug

When trying to upload a large file from a box with restricted bandwidth (100Mb/s) using multiple parts to S3 we receive an S3Exception with reason "The difference between the request time and the current time is too large. "

We checked the clocks on the server and clock sync was fine (under 2 seconds with S3 clock from what we can tell).

We believe the issue is that the upload is being split into multiple parts and at this point the headers for the upload are being generated but the actual uploading of the some of the parts is being delayed by up to 15 minutes (believe the timeout is 15 minutes https://web.archive.org/web/20170606231417/http://www.bucketexplorer.com/documentation/amazon-s3--difference-between-requesttime-currenttime-too-large.html) due to the restricted bandwidth, resulting in the upload to fail.

Expected Behavior

We would expect the upload to succeed rather than fail due to "The difference between the request time and the current time is too large"

Current Behavior

The below exception is thrown and the upload fails

Exception in thread "main" java.util.concurrent.CompletionException: software.amazon.awssdk.services.s3.model.S3Exception: The difference between the request time and the current time is too large. (Service: S3, Status Code: 403, Request ID: MN0F38BHPDRXNVPM, Extended Request ID: az4zMjKJfCKwkft8X4CFFuyp100bPk4ouYV8XsGGu1X5ROGc0iCrg8mkqJdj2fG0G3uUq3OPmP4=)
        at software.amazon.awssdk.utils.CompletableFutureUtils.errorAsCompletionException(CompletableFutureUtils.java:65)
        at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncExecutionFailureExceptionReportingStage.lambda$execute$0(AsyncExecutionFailureExceptionReportingStage.java:51)
        at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934)
        at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
        at software.amazon.awssdk.utils.CompletableFutureUtils.lambda$forwardExceptionTo$0(CompletableFutureUtils.java:79)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
        at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeAttemptExecute(AsyncRetryableStage.java:103)
        at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.maybeRetryExecute(AsyncRetryableStage.java:184)
        at software.amazon.awssdk.core.internal.http.pipeline.stages.AsyncRetryableStage$RetryingExecutor.lambda$attemptExecute$1(AsyncRetryableStage.java:170)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
        at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$null$0(MakeAsyncHttpRequestStage.java:105)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
        at software.amazon.awssdk.core.internal.http.pipeline.stages.MakeAsyncHttpRequestStage.lambda$executeHttpRequest$3(MakeAsyncHttpRequestStage.java:163)
        at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)
        at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)
        at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:482)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: software.amazon.awssdk.services.s3.model.S3Exception: The difference between the request time and the current time is too large. (Service: S3, Status Code: 403, Request ID: MN0F38BHPDRXNVPM, Extended Request ID: az4zMjKJfCKwkft8X4CFFuyp100bPk4ouYV8XsGGu1X5ROGc0iCrg8mkqJdj2fG0G3uUq3OPmP4=)
        at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handleErrorResponse(AwsXmlPredicatedResponseHandler.java:156)
        at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handleResponse(AwsXmlPredicatedResponseHandler.java:108)
        at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handle(AwsXmlPredicatedResponseHandler.java:85)
        at software.amazon.awssdk.protocols.xml.internal.unmarshall.AwsXmlPredicatedResponseHandler.handle(AwsXmlPredicatedResponseHandler.java:43)
        at software.amazon.awssdk.core.internal.handler.BaseClientHandler.lambda$successTransformationResponseHandler$7(BaseClientHandler.java:270)
        at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler.lambda$prepare$0(AsyncResponseHandler.java:89)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1150)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)
        at software.amazon.awssdk.core.internal.http.async.AsyncResponseHandler$BaosSubscriber.onComplete(AsyncResponseHandler.java:132)
        at software.amazon.awssdk.utils.async.SimplePublisher.doProcessQueue(SimplePublisher.java:275)
        at software.amazon.awssdk.utils.async.SimplePublisher.processEventQueue(SimplePublisher.java:224)
        at software.amazon.awssdk.utils.async.SimplePublisher.complete(SimplePublisher.java:157)
        at java.base/java.util.concurrent.CompletableFuture.uniRunNow(CompletableFuture.java:819)
        at java.base/java.util.concurrent.CompletableFuture.uniRunStage(CompletableFuture.java:803)
        at java.base/java.util.concurrent.CompletableFuture.thenRun(CompletableFuture.java:2195)
        at software.amazon.awssdk.services.s3.internal.crt.S3CrtResponseHandlerAdapter.onErrorResponseComplete(S3CrtResponseHandlerAdapter.java:135)
        at software.amazon.awssdk.services.s3.internal.crt.S3CrtResponseHandlerAdapter.handleError(S3CrtResponseHandlerAdapter.java:124)
        at software.amazon.awssdk.services.s3.internal.crt.S3CrtResponseHandlerAdapter.onFinished(S3CrtResponseHandlerAdapter.java:93)
        at software.amazon.awssdk.crt.s3.S3MetaRequestResponseHandlerNativeAdapter.onFinished(S3MetaRequestResponseHandlerNativeAdapter.java:24)

Reproduction Steps

This is the code we use to upload the file. Note that we run this code on 2 boxes in parallel

final S3CrtAsyncClientBuilder builder = S3AsyncClient.crtBuilder()
                .region(Region.EU_WEST_1)
                .httpConfiguration(
                        S3CrtHttpConfiguration
                                .builder()
                                .connectionTimeout(Duration.ofHours(4))
                                .build()
                )
                .credentialsProvider(awsCredentialsProvider)
                .minimumPartSizeInBytes(200L * 1024 * 1024);

        final S3AsyncClient s3Client = builder
                .build();
                
LOGGER.info("Uploading Bucket {} ObjectKey: {}", bucketName, objectKey);
        try (final S3TransferManager tm = S3TransferManager.builder().s3Client(s3Client).build())
        {
            LOGGER.info("Uploading a new object to S3 from a file\n");
            final FileUpload upload = tm.uploadFile(UploadFileRequest.builder()
                                                            .putObjectRequest(PutObjectRequest.builder().bucket(bucketName).key(objectKey).build())
                                                            .source(src)
                                                            .build());
            try
            {
                upload.completionFuture().join();
            }
            catch (final AwsServiceException ase)
            {
                LOGGER.info("Caught an AmazonServiceException, which means your request made it to Amazon S3, but was rejected with an error response for some reason.");
                LOGGER.info("Error Message:    " + ase.getMessage());
                LOGGER.info("HTTP Status Code: " + ase.statusCode());
                LOGGER.info("AWS Error Code:   " + ase.awsErrorDetails().errorCode());
                LOGGER.info("Error Type:       " + ase.awsErrorDetails().errorMessage());
                throw new IllegalStateException(ase);
            }
            catch (final SdkClientException ace)
            {
                LOGGER.info("Caught an AmazonClientException, which means the client encountered an internal error while trying to communicate with S3, such as not being able to access the network.");
                LOGGER.info("Error Message: " + ace.getMessage());
                throw new IllegalStateException(ace);
            }
        }

Possible Solution

Don't create the headers for each part of an upload until it's actually being uploaded.

Additional Information/Context

No response

AWS Java SDK version used

2.20.67

JDK version used

openjdk 17.0.6 2023-01-17 LTS OpenJDK Runtime Environment Corretto-17.0.6.10.1 (build 17.0.6+10-LTS) OpenJDK 64-Bit Server VM Corretto-17.0.6.10.1 (build 17.0.6+10-LTS, mixed mode, sharing)

Operating System and version

AlmaLinux 8.8 (Sapphire Caracal) Kernel: Linux 4.18.0-425.19.2.el8_7.x86_64

[debora-ito]

@tom-smalls Can you provide the CRT verbose wirelogs?
The verbose wirelogs will contain the time of each multipart request and the time of the server in the response.

Please refer to our Developer Guide for instructions on how to enable the wirelogs:
https://docs.aws.amazon.com/sdk-for-java/latest/developer-guide/logging-slf4j.html#sdk-java-logging-verbose

[github-actions]

It looks like this issue has not been active for more than five days. In the absence of more information, we will be closing this issue soon. If you find that this is still a problem, please add a comment to prevent automatic closure, or if the issue is already closed please feel free to reopen it.

[tom-smalls]

@debora-ito Yes, I can do this but will require me to do a patch release to production so will take a few days

[debora-ito]

@tom-smalls we don't recommend using verbose wirelogs in production, it can impact the application's performance and it will log sensitive data.

Can you reproduce the error in a non-prod environment?

[tom-smalls]

@debora-ito understood. Before trying to replicate in an environment, I am just testing the logging locally. Is this the sort of output you would be expecting?

[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: running scheduled tasks.
[DEBUG] [2023-07-25T12:11:26Z] [00007efcc89ee700] [task-scheduler] - id=0x7efca0109838: Running gather_statistics task with <Running> status
[DEBUG] [2023-07-25T12:11:26Z] [00007efcc89ee700] [channel] - id=0x7efca0109760: channel throughput - 0 bytes per second
[INFO] [2023-07-25T12:11:26Z] [00007efcc89ee700] [channel] - id=0x7efca0109760: Channel low throughput warning.  Currently 1000 milliseconds of consecutive failure time
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: scheduling task 0x7efca0109838 in-thread for timestamp 61829115645046
[DEBUG] [2023-07-25T12:11:26Z] [00007efcc89ee700] [task-scheduler] - id=0x7efca0109838: Scheduling gather_statistics task for future execution at time 61829115645046
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: detected more scheduled tasks with the next occurring at 63160787, using timeout of 63.
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: waiting for a maximum of 63 ms
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: wake up with 0 events to process.
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: running scheduled tasks.
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: detected more scheduled tasks with the next occurring at 23527, using timeout of 0.
[TRACE] [2023-07-25T12:11:26Z] [00007efcc89ee700] [event-loop] - id=0x7efd30587f50: waiting for a maximum of 0 ms

[debora-ito]

Yes, that looks like the CRT logs.

[tom-smalls]

I've compressed the file but it's too large for github (50MB with 25MB limit), I could upload to google drive or s3 if that works for you?

[debora-ito]

Yes, both options are good. Make sure they are securely shared and there's no sensitive data on the logs.

[tom-smalls]

Please see tar file

https://drive.google.com/file/d/1RKXdszbV6cmkoRc5Ixyb3qCafAfkfoDf/view?usp=sharing

[debora-ito]

@tom-smalls thank you for the logs, and sorry for the silence.

Yes, I can see there's a delay between the request for partNumber=31 being prepared:

[DEBUG] [2023-07-25T16:12:57Z] [00007fd903fff700] [S3MetaRequest] - 
        id=0x7fdb44a391a0: Prepared request 0x7fd9f4004480 for part 31
[TRACE] [2023-07-25T16:12:57Z] [00007fd903fff700] [S3MetaRequest] - 
        id=0x7fdb44a391a0 Created signable 0x7fd8fc02da90 for request 0x7fd9f4004480 with message 0x7fd8fc02dae0
[INFO] [2023-07-25T16:12:57Z] [00007fd903fff700] [AuthSigning] - 
        (id=0x7fd8fc02da90) Signing successfully built canonical request for algorithm SigV4, with contents (...)

and effectively being sent:

[TRACE] [2023-07-25T16:27:58Z] [00007fda437fe700] [S3MetaRequest] - 
        id=0x7fdb44a391a0: Sending request 0x7fd9f4004480
[TRACE] [2023-07-25T16:27:58Z] [00007fda437fe700] [S3MetaRequest] - 
        id=0x7fdb44a391a0 Incoming body for request 0x7fd9f4004480. Response status: 403. Data Size: 475. connection: 0x7fd9f4002820.
[TRACE] [2023-07-25T16:27:58Z] [00007fda437fe700] [S3MetaRequest] - response body: 
<Error>
    <Code>RequestTimeTooSkewed</Code>
    <Message>The difference between the request time and the current time is too large.</Message>
    <RequestTime>20230725T161257Z</RequestTime>
    <ServerTime>2023-07-25T16:27:59Z</ServerTime>
    <MaxAllowedSkewMilliseconds>900000</MaxAllowedSkewMilliseconds>
</Error>

I'll raise this to the CRT team. Preparing the request immediately before sending would avoid this kind of error.

[TingDaoK]

Hi, to unblock specific to your use case. I recommend to lower the targetThroughputInGbps, using here. Also, if possible, lowering the part size you using.

With the restricted bandwidth (100Mb/s), we can see from the log, one single request took 16 mins to finishes, that's causing the next request waits in the line for too long and result in the RequestTimeTooSkewed error. From, the log, we saw that we opened 30 concurrent connections, and they sharing the 100 Mb/s bandwidth to upload a 200 MB data, so, it's not a surprise that each request is taking that long and causing the error for other request.

So, simply set targetThroughputInGbps to 0.1 Gbps will probably solve your issue. And the recommended part size is 8 MB, it will also lower the time for request to finish and avoid the error you seen.

Besides of the settings to tweak, we are also adding a retry for the RequestTimeTooSkewed. That should also resolve the issue, here.

[tom-smalls]

We are going to try your recommended settings.

Do you have an idea of when awslabs/aws-c-s3#343 might be merged?

Thanks

[TingDaoK]

I just merged the PR, do you still have the issue after changing the configuration?

[tom-smalls]

I haven't tested yet, planning on testing this week

[tom-smalls]

It worked with the config changes.

[github-actions]

This issue is now closed. Comments on closed issues are hard for our team to see.
If you need more assistance, please open a new issue that references this one.