Intermittent 'Time is too skewed to adjust' errors after upgrading aws-java-sdk from 1.11.759 to 1.11.768

jhungerford commented 4 years ago

I work on a Java 11 service running on centos in EC2 that makes 10's of thousands of AWS API calls every hour. After upgrading the sdk from 1.11.759 to 1.11.768, roughly 0.1% of API requests fail with:

java.lang.IllegalStateException: Time is too skewed to adjust: (clientTime: 1588097015366, serverTime: -61525806985000

Most come from the RDS and Redshift RI describe endpoints, but I've also seen the same issue when sending messages to SQS.

I'm not sure if this is related to #2304 - my understanding is that the clock sku correction is used to make the auth token more reliable, but I'm seeing a different stack trace than the one in that issue.

Current Behavior

Example stack traces:

Sending a message to SQS:

ErrorView{errorCode=internal_server_error, message=There was an error processing the request. You may attempt to retry following a back-off policy. Please refer to the 'locator' code when contacting support. Internal Server Error, locator=d83b2d0ed46a74a9, details=null, internalDetails={internalMessage=Time is too skewed to adjust: (
clientTime: 1588097015366, serverTime: -61525806985000), exStack=java.lang.IllegalStateException: Time is too skewed to adjust: (clientTime: 1588097015366, serverTime: -61525806985000)
        at com.amazonaws.retry.ClockSkewAdjuster.timeSkewInSeconds(ClockSkewAdjuster.java:155)
        at com.amazonaws.retry.ClockSkewAdjuster.updateEstimatedSkew(ClockSkewAdjuster.java:81)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(AmazonHttpClient.java:1363)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1145)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:802)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:770)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:744)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:704)
        at com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:686)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:550)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:530)
        at com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:2207)
        at com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:2174)
        at com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:2163)
        at com.amazonaws.services.sqs.AmazonSQSClient.executeSendMessage(AmazonSQSClient.java:1762)
        at com.amazonaws.services.sqs.AmazonSQSClient.sendMessage(AmazonSQSClient.java:1734)
        at com.amazonaws.services.sqs.AmazonSQSClient.sendMessage(AmazonSQSClient.java:1774)
        ...

Describe RDS Reserved Instances:

java.lang.IllegalStateException: Time is too skewed to adjust: (clientTime: 1588097811398, serverTime: -61525806189000)
        at com.amazonaws.retry.ClockSkewAdjuster.timeSkewInSeconds(ClockSkewAdjuster.java:155) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.retry.ClockSkewAdjuster.updateEstimatedSkew(ClockSkewAdjuster.java:81) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(AmazonHttpClient.java:1363) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1145) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:802) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:770) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:744) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:704) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:686) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:550) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:530) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.services.rds.AmazonRDSClient.doInvoke(AmazonRDSClient.java:9620) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.services.rds.AmazonRDSClient.invoke(AmazonRDSClient.java:9587) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.services.rds.AmazonRDSClient.invoke(AmazonRDSClient.java:9576) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        at com.amazonaws.services.rds.AmazonRDSClient.executeDescribeReservedDBInstances(AmazonRDSClient.java:5876) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-producti
on]
        at com.amazonaws.services.rds.AmazonRDSClient.describeReservedDBInstances(AmazonRDSClient.java:5847) ~[sudo-server-1.56-SNAPSHOT-51-branch-production.jar:1.56-SNAPSHOT-51-branch-production]
        ...

Steps to Reproduce

Since such a low percentage of requests fail because of clock sku, I haven't been able to reliably reproduce this issue. The reported serverTime varies between requests, and I've seen the error from several different regions.

In millis since the epoch, -61525806985000 is ~51AD, so another possibility that I'm considering is that AWS unearthed an ancient roman data center while opening the new region in Milan.

Your Environment

AWS Java SDK version used: 1.11.768

JDK version used:

$ java -version
openjdk version "11.0.4" 2019-07-16
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.4+11)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.4+11, mixed mode)

Operating System and version:

$ cat /etc/system-release
CentOS Linux release 7.7.1908 (Core)

will-amp commented 4 years ago

I am having the same problem after upgrading to aws-java-sdk-s3 version 1.11.769

zoewangg commented 4 years ago

Thanks for reporting the issue, taking a look

zoewangg commented 4 years ago

Hi @jhungerford, @will-amp, we have pushed out a fix, and it's available in 1.11.772 Could you try with the latest version? https://github.com/aws/aws-sdk-java/blob/master/CHANGELOG.md#111772-2020-04-29

jhungerford commented 4 years ago

Thanks - that was fast! I'll update our code to use 1.11.772, and report back here after I've let it soak for a while.

jhungerford commented 4 years ago

I haven't seen any more clock skew request failures after upgrading to 1.11.772 - thanks again!

aws / aws-sdk-java