S3 snapshotting times out requiring Elasticsearch process restart

[ccoffey]

Elasticsearch version (bin/elasticsearch --version):

curl -X GET "localhost:9200"
{
  "name" : "redacted",
  "cluster_name" : "redacted",
  "cluster_uuid" : "UJ8NSWbXSQmErxP9IfbvNA",
  "version" : {
    "number" : "6.3.0",
    "build_flavor" : "default",
    "build_type" : "rpm",
    "build_hash" : "424e937",
    "build_date" : "2018-06-11T23:38:03.357887Z",
    "build_snapshot" : false,
    "lucene_version" : "7.3.1",
    "minimum_wire_compatibility_version" : "5.6.0",
    "minimum_index_compatibility_version" : "5.0.0"
  },
  "tagline" : "You Know, for Search"
}

Plugins installed: [repository-s3, discovery-ec2]

JVM version (java -version):

java version "1.8.0_171"
Java(TM) SE Runtime Environment (build 1.8.0_171-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.171-b11, mixed mode)

OS version (uname -a if on a Unix-like system):

Linux es-client-1 4.14.88-72.76.amzn1.x86_64 #1 SMP Mon Jan 7 19:47:07 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

Snapshotting is failing for us with the following error

{
  "duration_in_millis": 345001,
  "end_time": "2019-02-02T00:05:48.480Z",
  "end_time_in_millis": 1549065948480,
  "failures": [
    {
      "index": "redacted",
      "index_uuid": "redacted",
      "node_id": "lxtigl9JRvm1dLX0RurmUg",
      "reason": "IndexShardSnapshotFailedException[com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SdkClientException[Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: ConnectTimeoutException[Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SocketTimeoutException[connect timed out]; ",
      "shard_id": 11,
      "status": "INTERNAL_SERVER_ERROR"
    },
    {
      "index": "redacted",
      "index_uuid": "redacted",
      "node_id": "lxtigl9JRvm1dLX0RurmUg",
      "reason": "IndexShardSnapshotFailedException[com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SdkClientException[Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: ConnectTimeoutException[Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SocketTimeoutException[connect timed out]; ",
      "shard_id": 13,
      "status": "INTERNAL_SERVER_ERROR"
    },
    {
      "index": "redacted",
      "index_uuid": "redacted",
      "node_id": "lxtigl9JRvm1dLX0RurmUg",
      "reason": "IndexShardSnapshotFailedException[com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SdkClientException[Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: ConnectTimeoutException[Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SocketTimeoutException[connect timed out]; ",
      "shard_id": 11,
      "status": "INTERNAL_SERVER_ERROR"
    },
    {
      "index": "redacted",
      "index_uuid": "redacted",
      "node_id": "lxtigl9JRvm1dLX0RurmUg",
      "reason": "IndexShardSnapshotFailedException[com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SdkClientException[Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: ConnectTimeoutException[Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SocketTimeoutException[connect timed out]; ",
      "shard_id": 14,
      "status": "INTERNAL_SERVER_ERROR"
    },
    {
      "index": "redacted",
      "index_uuid": "redacted",
      "node_id": "lxtigl9JRvm1dLX0RurmUg",
      "reason": "IndexShardSnapshotFailedException[com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SdkClientException[Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: ConnectTimeoutException[Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SocketTimeoutException[connect timed out]; ",
      "shard_id": 12,
      "status": "INTERNAL_SERVER_ERROR"
    },
    {
      "index": "redacted",
      "index_uuid": "redacted",
      "node_id": "lxtigl9JRvm1dLX0RurmUg",
      "reason": "IndexShardSnapshotFailedException[com.amazonaws.SdkClientException: Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SdkClientException[Unable to execute HTTP request: Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: ConnectTimeoutException[Connect to redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/52.216.176.27] failed: connect timed out]; nested: SocketTimeoutException[connect timed out]; ",
      "shard_id": 19,
      "status": "INTERNAL_SERVER_ERROR"
    }
  ],
  "include_global_state": true,
  "indices": [
    "redacted",
    "redacted",
    "redacted",
    "redacted",
    "redacted",
    "redacted",
    "redacted",
    "redacted",
    "redacted",
    "redacted"
  ],
  "shards": {
    "failed": 6,
    "successful": 194,
    "total": 200
  },
  "snapshot": "redacted_2019-02-02t00:00:03z",
  "start_time": "2019-02-02T00:00:03.479Z",
  "start_time_in_millis": 1549065603479,
  "state": "PARTIAL",
  "uuid": "mbCeCSWuTXWkauPLgNq3Hg",
  "version": "6.3.0",
  "version_id": 6030099
}

Note: The 6 shards that failed to snapshot were all on the same host lxtigl9JRvm1dLX0RurmUg. Every subsequent attempt to create a snapshot results in the exact same error, with only this single node failing with a timeout to S3.

Restarting the Elasticsearch process on this host, waiting for the cluster to go green, and then snapshotting again is successful.

This is a pretty serious problem for us, we need to be able to reliably take snapshots every 24 hours. If there is more information you need us to provide in order to get this triaged, please let us know.

[ccoffey]

The Java virtual machine (JVM) caches DNS name lookups. When the JVM resolves a hostname to an IP address, it caches the IP address for a specified period of time, known as the time-to-live (TTL).

Because AWS resources use DNS name entries that occasionally change, we recommend that you configure your JVM with a TTL value of no more than 60 seconds. This ensures that when a resource's IP address changes, your application will be able to receive and use the resource's new IP address by requerying the DNS.

On some Java configurations, the JVM default TTL is set so that it will never refresh DNS entries until the JVM is restarted. Thus, if the IP address for an AWS resource changes while your application is still running, it won't be able to use that resource until you manually restart the JVM and the cached IP information is refreshed. In this case, it's crucial to set the JVM's TTL so that it will periodically refresh its cached IP information.

This ^ seems likely to be the root cause:
https://docs.aws.amazon.com/sdk-for-java/v1/developer-guide/java-dg-jvm-ttl.html

Should you guys be setting this TTL somewhere in this repo? https://github.com/elastic/elasticsearch/tree/master/plugins/repository-s3

[ccoffey]

Just in case it's useful, according to the Elasticsearch log, we are NOT passing any JVM arg that could be overriding any ttl defaults.

[2019-02-02T14:33:52,392][INFO ][o.e.n.Node ] [es-master-3.localdomain] version[6.3.0], pid[27981], build[default/rpm/424e937/2018-06-11T23:38:03.357887Z], OS[Linux/4.14.88-72.76.amzn1.x86_64/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/1.8.0_171/25.171-b11]

[2019-02-02T14:33:52,392][INFO ][o.e.n.Node ] [es-master-3.localdomain] JVM arguments [-Xms7789m, -Xmx7789m, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -XX:+PrintTenuringDistribution, -XX:+PrintGCApplicationStoppedTime, -Xloggc:logs/gc.log, -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=32, -XX:GCLogFileSize=64m, -Des.index.memory.max_index_buffer_size=10240mb, -Des.path.home=/usr/share/elasticsearch, -Des.path.conf=/etc/elasticsearch, -Des.distribution.flavor=default, -Des.distribution.type=rpm]

[DaveCTurner]

If the issue is DNS caching, see #36570 which I think should fix this in ≥6.6.0.

[elasticmachine]

Pinging @elastic/es-distributed

[jasontedor]

Since you have triaged this as a DNS caching issue, you have two options:

• in 6.3.0, override the infinite DNS cache in your security policy
• upgrade to 6.6.0 where we override the infinite DNS cache by default

Please let us know if this addresses your issue.

[ccoffey]

For option 1: I believe I have found the correct file

head -n3 $JAVA_HOME/jre/lib/security/java.security
#
# This is the "master security properties file".
#

Am I correct in saying I need to append the following two lines to this file (values taken from your PR)

networkaddress.cache.ttl=60
networkaddress.cache.negative.ttl=10

And then I need to restart the Elasticsearch process?

[ccoffey]

@jasontedor I have not been able to prove that option 1 works.

Here is what I did on a test cluster.

1. Checked which version of java the Elasticsearch process is using

ps aux | grep elasticsearch
495      13082  5.6 54.5 11676924 8393576 ?    SLl  14:29   0:47 /usr/bin/java ...

1. Found the location of java.home

/usr/bin/java -XshowSettings:properties -version 2>&1 | grep java.home
    java.home = /usr/lib/jvm/jdk1.8.0_171/jre

According to the docs the file I need to edit is java.home/lib/security/java.security so /usr/lib/jvm/jdk1.8.0_171/jre/lib/security/java.security

2. I made sure that the cluster could talk to S3

curl -X GET 'localhost:9200/_snapshot/my_backup/_all?pretty'
[{
      "snapshot" : "redacted",
      "uuid" : "bqsiTs04RJCVhMlx8W0XxQ",
      "version_id" : 6030099,
      "version" : "6.3.0",
      "indices" : [
        "redacted"
      ],
      "include_global_state" : true,
      "state" : "SUCCESS",
      "start_time" : "2019-02-04T11:16:32.825Z",
      "start_time_in_millis" : 1549278992825,
      "end_time" : "2019-02-04T11:19:25.602Z",
      "end_time_in_millis" : 1549279165602,
      "duration_in_millis" : 172777,
      "failures" : [ ],
      "shards" : {
        "total" : 331,
        "failed" : 0,
        "successful" : 331
      }
    }
}]

3. I edited /etc/hosts on all master eligible nodes so that they could no longer talk to S3

tail -n1 /etc/hosts 
1.2.3.4 redacted.s3.amazonaws.com

4. I edited java.security to turn on ttl-ing

grep 'networkaddress.cache.ttl' /usr/lib/jvm/jdk1.8.0_171/jre/lib/security/java.security
networkaddress.cache.ttl=60

5. I restarted the Elasticsearch process on all master eligible nodes

6. I verified that the cluster could no longer talk to S3

curl -X GET 'localhost:9200/_snapshot/my_backup/_all?pretty' 
{
  "error": {
    "reason": "[my_backup] missing",
    "root_cause": [
      {
        "reason": "[my_backup] missing",
        "type": "repository_missing_exception"
      }
    ],
    "type": "repository_missing_exception"
  },
  "status": 404
}

7. I edited /etc/hosts on all master eligible nodes so that they could talk to S3 again

tail -n1 /etc/hosts 
#1.2.3.4 redacted.s3.amazonaws.com

8. I waited 1 minute and expected to be able to talk to S3

curl -X GET 'localhost:9200/_snapshot/my_backup/_all?pretty'
{
  "error" : {
    "root_cause" : [
      {
        "type" : "repository_missing_exception",
        "reason" : "[my_backup] missing"
      }
    ],
    "type" : "repository_missing_exception",
    "reason" : "[my_backup] missing"
  },
  "status" : 404
}

9. I waited another 10 minutes and still the same thing (I was not expecting this, the TTL should have expired by now)

curl -X GET 'localhost:9200/_snapshot/my_backup/_all?pretty'
{
  "error" : {
    "root_cause" : [
      {
        "type" : "repository_missing_exception",
        "reason" : "[my_backup] missing"
      }
    ],
    "type" : "repository_missing_exception",
    "reason" : "[my_backup] missing"
  },
  "status" : 404
}

10. I restarted the Elasticsearch process on all master eligible nodes and I could talk to S3 again

curl -X GET 'localhost:9200/_snapshot/my_backup/_all?pretty'
[{
      "snapshot" : "redacted",
      "uuid" : "bqsiTs04RJCVhMlx8W0XxQ",
      "version_id" : 6030099,
      "version" : "6.3.0",
      "indices" : [
        "redacted"
      ],
      "include_global_state" : true,
      "state" : "SUCCESS",
      "start_time" : "2019-02-04T11:16:32.825Z",
      "start_time_in_millis" : 1549278992825,
      "end_time" : "2019-02-04T11:19:25.602Z",
      "end_time_in_millis" : 1549279165602,
      "duration_in_millis" : 172777,
      "failures" : [ ],
      "shards" : {
        "total" : 331,
        "failed" : 0,
        "successful" : 331
      }
    }
}]

[jasontedor]

@original-brownbear Can you take a look?

[original-brownbear]

@jasontedor sure will do :)

[original-brownbear]

@ccoffey I just manually tried this out using Elasticsearch 6.3, following your exact steps.
I was able to reproduce the exact issue of the cache not refreshing without the DNS TTL manually adjusted, but unlike for you it was fixed by setting the TTL in the java.security file.
Also tried this out in 6.6 and it worked fine out of the box there as @jasontedor suggested

So as far I can see this is a problem with your environment not picking up the setting for some reason.
One thing you could try to rule out that your system loads the wrong java.security file for some reason is to add

-Djava.security.properties=/usr/lib/jvm/jdk1.8.0_171/jre/lib/security/java.security

to elasticsearch's config/jvm.options file.

Since we reserve Github for confirmed bugs and feature requests I am going to close this issue and would suggest opening a thread on this topic on our discuss forum.

[andrejbl]

@original-brownbear - thanks for investigating this. Indeed, you are correct, the steps we performed above do fix the problem with infinite DNS caching and the real issue was with our repro setup.

However, the repro setup we used surfaced a different caching issue at another level. Namely, the error we observed:

curl -X GET 'localhost:9200/_snapshot/my_backup/_all?pretty'
{
  "error" : {
    "root_cause" : [
      {
        "type" : "repository_missing_exception",
        "reason" : "[my_backup] missing"
      }
    ],
    "type" : "repository_missing_exception",
    "reason" : "[my_backup] missing"
  },
  "status" : 404
}

is not the one we expected from a stale DNS entry caching bug, which would have looked like this:

"root_cause":[{"type":"sdk_client_exception","reason":"sdk_client_exception: Unable to execute HTTP request: Connect to i
redacted.s3.amazonaws.com:443 [redacted.s3.amazonaws.com/X.X.X.X] failed: connect timed out"}]

The 404 error started being returned indefinitely after we 1) created the fake /etc/hosts entry and 2) restarted elasticsearch.

What seems to happen is that if a snapshot is not reachable at ES startup time (as opposed to running time), the ES indefinitely starts returning 404 errors back to the caller for any snapshot operations, regardless of later DNS or snapshot connectivity changes.