ES Rest High Level Client throws SocketTimeoutException after being idle for sometime [DATAES-815]

[spring-projects-issues]

Ori Doolman opened DATAES-815 and commented

After the application (client) is idle for some time, the first request to ES always fail with a timeout error.

The following log is from SpringBoot 2.2.6, but I reproduced the same on 2.3.0.M4.

 

caused by: java.net.SocketTimeoutException: 5,000 milliseconds timeout on connection http-outgoing-0 [ACTIVE] at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:944) ~[elasticsearch-rest-client-6.8.7.jar:6.8.7] at org.elasticsearch.client.RestClient.performRequest(RestClient.java:233) ~[elasticsearch-rest-client-6.8.7.jar:6.8.7] at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:1764) ~[elasticsearch-rest-high-level-client-6.8.7.jar:6.8.7] at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:1734) ~[elasticsearch-rest-high-level-client-6.8.7.jar:6.8.7] at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:1696) ~[elasticsearch-rest-high-level-client-6.8.7.jar:6.8.7] at org.elasticsearch.client.RestHighLevelClient.search(RestHighLevelClient.java:1092) ~[elasticsearch-rest-high-level-client-6.8.7.jar:6.8.7] at org.springframework.data.elasticsearch.core.ElasticsearchRestTemplate.doSearch(ElasticsearchRestTemplate.java:1152) ~[spring-data-elasticsearch-3.2.6.RELEASE.jar:3.2.6.RELEASE] ... 152 common frames omitted Caused by: java.net.SocketTimeoutException: 5,000 milliseconds timeout on connection http-outgoing-0 [ACTIVE] at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.timeout(HttpAsyncRequestExecutor.java:387) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.client.InternalIODispatch.onTimeout(InternalIODispatch.java:92) ~[httpasyncclient-4.1.4.jar:4.1.4] at org.apache.http.impl.nio.client.InternalIODispatch.onTimeout(InternalIODispatch.java:39) ~[httpasyncclient-4.1.4.jar:4.1.4] at org.apache.http.impl.nio.reactor.AbstractIODispatch.timeout(AbstractIODispatch.java:175) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.reactor.BaseIOReactor.sessionTimedOut(BaseIOReactor.java:261) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.reactor.AbstractIOReactor.timeoutCheck(AbstractIOReactor.java:502) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.reactor.BaseIOReactor.validate(BaseIOReactor.java:211) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:280) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104) ~[httpcore-nio-4.4.13.jar:4.4.13] at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:591) ~[httpcore-nio-4.4.13.jar:4.4.13] ... 1 common frames omitted

 

I tried setting the connection timeout and the socket timeout to 0 in the client configuration, but it did not help. I just got a different type of exception.

Here is how I configure my client:

 

clientConfiguration = ClientConfiguration.builder()
        .connectedTo(esHost + ":" + esPort)
        .usingSsl()
        //.withConnectTimeout(0)
        .build();

RestHighLevelClient client = RestClients.create(clientConfiguration).rest();

 

 

 

---

Affects: 4.0 RC2 (Neumann)

Reference URL: https://stackoverflow.com/questions/56815933/es-rest-high-level-client-throws-sockettimeoutexception-after-being-idle-for-som

[spring-projects-issues]

sothawo commented

You give as environment ES 7.3 and Spring Data Elasticsearch 4.0.RC2, but your logs show that your application uses the ES client libs 6.8.7. That means you are using Spring Data Elasticsearch 3.2.

In Spring Data Elasticsearch 4.0, this should come up as a DataAccessResourceFailureException which you would need to handle yourself. You could do that like I wrote in the comments of DATAES-760

[spring-projects-issues]

Ori Doolman commented

sothawo, thank you for the answer.

As I wrote in the original comment, the logs are from springboot 2.2.6, but I get them in 2.3.0.M4 (spring-data-elasticsearch-4.0.0.RC1) as well:

 

2020-05-07 10:43:33.731 TRACE 45956 --- [nio-8090-exec-8] o.s.data.elasticsearch.client.WIRE       : [29cd7f49] Sending request POST /books-11111111-c929-462e-ade4-074c81643191/_search?pre_filter_shard_size=128&typed_keys=true&max_concurrent_shard_requests=5&ignore_unavailable=false&expand_wildcards=open&allow_no_indices=true&ignore_throttled=true&search_type=dfs_query_then_fetch&batched_reduce_size=512&ccs_minimize_roundtrips=true with parameters: 2020-05-07 10:43:33.731 TRACE 45956 --- [nio-8090-exec-8] o.s.data.elasticsearch.client.WIRE       : [29cd7f49] Sending request POST /books-11111111-c929-462e-ade4-074c81643191/_search?pre_filter_shard_size=128&typed_keys=true&max_concurrent_shard_requests=5&ignore_unavailable=false&expand_wildcards=open&allow_no_indices=true&ignore_throttled=true&search_type=dfs_query_then_fetch&batched_reduce_size=512&ccs_minimize_roundtrips=true with parameters: Request body: {"from":0,"size":50,"query":{"wildcard":{"title.keyword":{"wildcard":"*pro*","boost":1.0}}},"version":true}2020-05-07 10:43:38.743  WARN 45956 --- [nio-8090-exec-8] c.c.n.a.web.GlobalExceptionHandler       : Server error when trigger from REST Controller
org.springframework.dao.DataAccessResourceFailureException: 5,000 milliseconds timeout on connection http-outgoing-1 [ACTIVE]; nested exception is java.lang.RuntimeException: 5,000 milliseconds timeout on connection http-outgoing-1 [ACTIVE] at org.springframework.data.elasticsearch.core.ElasticsearchExceptionTranslator.translateExceptionIfPossible(ElasticsearchExceptionTranslator.java:62) ~[spring-data-elasticsearch-4.0.0.RC1.jar:4.0.0.RC1] at org.springframework.data.elasticsearch.core.ElasticsearchRestTemplate.translateException(ElasticsearchRestTemplate.java:359) ~[spring-data-elasticsearch-4.0.0.RC1.jar:4.0.0.RC1] at org.springframework.data.elasticsearch.core.ElasticsearchRestTemplate.execute(ElasticsearchRestTemplate.java:342) ~[spring-data-elasticsearch-4.0.0.RC1.jar:4.0.0.RC1] at org.springframework.data.elasticsearch.core.ElasticsearchRestTemplate.search(ElasticsearchRestTemplate.java:260) ~[spring-data-elasticsearch-4.0.0.RC1.jar:4.0.0.RC1] at org.springframework.data.elasticsearch.repository.support.AbstractElasticsearchRepository.search(AbstractElasticsearchRepository.java:227) ~[spring-data-elasticsearch-4.0.0.RC1.jar:4.0.0.RC1] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]

 

I will try to implement the retry mechanism you suggested in DATAES-760 and let you know if it helped.

However, I think it would be great if the root cause for this exception can be somehow handled.

 

 

[spring-projects-issues]

Ori Doolman commented

hi sothawo,

I've implemented the solution you suggested, and it is working (kind of).

I do get the 200 OK result in the client application, but it is still takes 5000 millisecond for the first request after idle time, because the exception still occurs.

I'm not sure if that is a very good workaround. 

[spring-projects-issues]

sothawo commented

It depends on the value that you set for the socket timeout. If you set this lower than 5 seconds, then the second call will be done faster (a value of 0 for the timeout means no timeout will be set)

[spring-projects-issues]

Ori Doolman commented

sothawo, 

Yes - this is what I planned to do.

Is there any risk of setting the connection timeout to 0? Will it affect any other place?  

[spring-projects-issues]

sothawo commented

no timeout means exactly that - waiting forever

[spring-projects-issues]

sothawo commented

you could set it to a low value like 100ms, but then it triggers when the answer from ES takes longer than that, although there would be no problem. To find a value that fits your problem, you will have to try different values

[spring-projects-issues]

Ori Doolman commented

Hi sothawo,

I've implemented the retry as you wrote above, but it doesn't fully resolve the issue in all cases.

This is because the RestClient is holding a pool of connections. And one retry doesn't help when one connection experienced timeout and the retry randomly chooses another connection which is also experiencing a similar timeout.

I'm experiencing this timeout even though I'm connected to a multi-node cluster (AWS Elasticsearch). 

Therefore, I think there is some kind of a bug in the RestClient or maybe even in the underlying HttpAsyncClient.

 

To overcome that, I've refactored your retry workaround to retry multiple times (I took the number of connections as a retry limit).

However, this feels to me as a workaround and not a really full solution to the issue. 

 

Here is the code I used when initializing the client:

@Override
public ElasticsearchOperations elasticsearchOperations(ElasticsearchConverter elasticsearchConverter) {
    return new ElasticsearchRestTemplate(elasticsearchClient(), elasticsearchConverter) {
        int retryCount = 0;
        @Override
        public <T> T execute(ClientCallback<T> callback) {
            T t = null;
            while (retryCount < RestClientBuilder.DEFAULT_MAX_CONN_PER_ROUTE && t == null) {
                try {
                    t = super.execute(callback);
                    retryCount = 0;
                } catch (DataAccessResourceFailureException e) {
                    // retry
                    retryCount++;
                    if (retryCount >= RestClientBuilder.DEFAULT_MAX_CONN_PER_ROUTE) {
                        retryCount = 0;
                        throw e;
                    }
                    log.warn("Elasticsearch client - performing retry {} after caught DataAccessResourceFailureException: {}", retryCount, e.getMessage());
                }
            }
            return t;
        }
    };
}

 

Can you re-open the issue and suggest a better solution/fix?

 

Regardless, I think it would be nice if I could set the number of pool connections externally, when configuring the RestHighLevelClient.

 

Regards,

Ori.

 

 

[spring-projects-issues]

sothawo commented

As I wrote in DATAES-760 this connection pooling stuff is in the Elasticsearch code and nothing we can really influence. We only use the RestHighLevelClient ourselves. So a solution would be not different from what you have implemented.

But we can add configuration properties for the maxConnTotal and maxConnPerRoute values of the HttpClient, please create a new issue for that

[spring-projects-issues]

Ori Doolman commented

Hi sothawo,

 

1. I've created a new issue for that in elastic github - https://github.com/elastic/elasticsearch/issues/59261 

2. I've created a new issue regarding the HttpClient configuration - https://jira.spring.io/browse/DATAES-882

Thank you,

Ori.

 

[spring-projects-issues]

Ori Doolman commented

Here is my latest workaround code, in case someone will want to use it.

Updates from previous code:

• moved retryCount to be local variable
• Only retry in case of SocketTimeoutException

 

// code placeholder
@Override
public ElasticsearchOperations elasticsearchOperations(ElasticsearchConverter elasticsearchConverter) {
    return new ElasticsearchRestTemplate(elasticsearchClient(), elasticsearchConverter) {
        @Override
        public <T> T execute(ClientCallback<T> callback) {
            int retryCount = 0;
            T t = null;
            while (retryCount <= RestClientBuilder.DEFAULT_MAX_CONN_PER_ROUTE && t == null) {
                try {
                    t = super.execute(callback);
                } catch (DataAccessResourceFailureException e) {
                    // retry
                    if (e.getCause() != null && (e.getCause().getCause() instanceof SocketTimeoutException) &&
                            (retryCount < RestClientBuilder.DEFAULT_MAX_CONN_PER_ROUTE)) {
                        retryCount++;
                        log.warn("Elasticsearch client - performing retry {} after caught DataAccessResourceFailureException: {}", retryCount, e.getMessage());
                    }
                    else {
                        throw e;
                    }
                }
            }
            return t;
        }
    };
}

Ori.