前言
在使用elastic客户端的时候我们有多种选择，之前在公司封装的es-client就支持了spring-data-es、jest、官方high-level-client等。有个小伙伴过来问，我配置了readTimeout为5ms，为啥不生效呢？带着疑问开始摸索，发现是有个默认配置的问题引起的，过程花了不少时间，所以总结一下，避免下次遇到类似问题还踩坑。
访问超时现象还原
一开始怀疑是我封装的客户端的问题，所以直接用原生的客户端抛下demo，排除原生客户端就存在此问题。代码如下：
public class Es7RestTimeoutSimpleTest extends BaseTest {
@Test
public void run() throws Exception {
String nodes = "X.X.X.X:9200";
String[] nodesArray = nodes.split(";");
HttpHost[] httpHosts = new HttpHost[nodesArray.length];
for (int i = 0; i < nodesArray.length; i++) {
String[] values = nodesArray[i].split(":");
httpHosts[i] = new HttpHost(values[0], Integer.parseInt(values[1]), "http");
}
RestClientBuilder builder = RestClient.builder(httpHosts);;
builder.setRequestConfigCallback(requestConfigBuilder -> {
requestConfigBuilder.setConnectTimeout(1000);
// 设置为1ms，按道理一定会触发超时
requestConfigBuilder.setSocketTimeout(1);
requestConfigBuilder.setConnectionRequestTimeout(30000);
return requestConfigBuilder;
});
final CredentialsProvider credentialsProvider = new BasicCredentialsProvider();
credentialsProvider.setCredentials(AuthScope.ANY,
new UsernamePasswordCredentials("test", "test"));
// 认证
builder.setHttpClientConfigCallback(httpClientBuilder -> {
httpClientBuilder.setDefaultCredentialsProvider(credentialsProvider);
httpClientBuilder.setMaxConnPerRoute(10);
httpClientBuilder.setMaxConnTotal(10);
//httpClientBuilder.setDefaultIOReactorConfig(
// IOReactorConfig.custom().setSelectInterval(1).build());
return httpClientBuilder;
});
RestHighLevelClient restHighLevelClient = new RestHighLevelClient(builder);
System.out.println("=======================================get");
GetRequest get = new GetRequest("es-sdk-test1").id("1");
StopWatch stopWatch = new StopWatch("get");
stopWatch.start();
GetResponse createIndexResponseSelect = restHighLevelClient.get(get, RequestOptions.DEFAULT);
stopWatch.stop();
System.out.println("get cost:" + stopWatch.getTotalTimeMillis());
System.out.println(createIndexResponseSelect.toString());
}
}
上面代码中设置读取超时时间为1ms，正常情况这个查询一定会超时。但是运行后发现，一点错误没有哈，懵逼了，因为api很清晰，抱着官方sdk一定没有bug，是不是需要初始化代码少了什么呢？所以就去看官方文档，查看配置超时时间正确的姿势是如何写的。
官方文档针对超时时间的设置有个例子，我截图放到文稿中：
看了几遍发现和我写的配置也没什么区别呢？为啥就是不生效了，然后有怀疑是客户端版本的问题，我就升级到7.10的版本（原本我是7.5.2），其实这个地方当时可以跳过，既然版本有这个api就不会有问题，这个case太普通了，版本bug的概率很小很小。
一个线索
想了想，首先还是看网上有没有类似开发遇到这个问题，stackflow、csdn都找过好多，发现大部分就是官方文档的重复，都是如何配超时。
没有办法，只能一行代码一行代码debug，刚开始的debug重心都放在timeout初始化的地方，所以浪费了大量时间。high-level-client底层也是使用httpcomponents组件做的http请求，里面都是nio异步的，我就在通信的地方打断点，位置为：org.apache.http.impl.nio.reactor.AbstractIOReactor.timeoutCheck(AbstractIOReactor.java:492)
这里无意中停留的时间比较长，发现socketTimeout值没有问题是1，有1、2次确实也触发了超时错误，但是怀疑是因为自己debug停留时间过长影响的就没在意。兜兜转转，太晚了就想明天再看。
准确定位
第二天有思路了，既然debug能触发异常堆栈，那么根据堆栈分析是哪个条件判断超时就可以了啊，所以就花时间重现错误，也花了一些时间复现了之前debug，然后出现超时错误。堆栈如下：
java.net.SocketTimeoutException: 1 milliseconds timeout on connection http-outgoing-0 [ACTIVE]
at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:808)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:248)
at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235)
at org.elasticsearch.client.RestHighLevelClient.internalPerformRequest(RestHighLevelClient.java:1514)
at org.elasticsearch.client.RestHighLevelClient.performRequest(RestHighLevelClient.java:1484)
at org.elasticsearch.client.RestHighLevelClient.performRequestAndParseEntity(RestHighLevelClient.java:1454)
at org.elasticsearch.client.RestHighLevelClient.get(RestHighLevelClient.java:742)
at Es7RestTimeoutSimpleTest.run(Es7RestTimeoutSimpleTest.java:67)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:220)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:53)
Caused by: java.net.SocketTimeoutException: 1 milliseconds timeout on connection http-outgoing-0 [ACTIVE]
at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.timeout(HttpAsyncRequestExecutor.java:387)
at org.apache.http.impl.nio.client.InternalIODispatch.onTimeout(InternalIODispatch.java:92)
at org.apache.http.impl.nio.client.InternalIODispatch.onTimeout(InternalIODispatch.java:39)
at org.apache.http.impl.nio.reactor.AbstractIODispatch.timeout(AbstractIODispatch.java:175)
at org.apache.http.impl.nio.reactor.BaseIOReactor.sessionTimedOut(BaseIOReactor.java:263)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.timeoutCheck(AbstractIOReactor.java:492)
at org.apache.http.impl.nio.reactor.BaseIOReactor.validate(BaseIOReactor.java:213)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:280)
at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:591)
at java.lang.Thread.run(Thread.java:748)
从堆栈可以看出配置的超时时间值就是我设置的，那为啥什么debug就偶尔复现，非debug就没问题了。问题出在BaseIOReactor.validate这个方法，代码如下：
在validate超时的时候，有个关键条件。需要满足当前时间和上次检查时间之差大于timeoutCheckInterval（debug的值为1000），也就是有个超时时间检查的间隔时间。那么问题简单了，找到timeoutCheckInterval配置的地方就可以了。这个过程也有点周折，最后知道是RestClientBuilder配置httpClientBuilder可以设置，然后摸索到配置的方式为：
httpClientBuilder.setDefaultIOReactorConfig(IOReactorConfig.custom().setSelectInterval(1).build());
总结问题
这个问题排查时间超过预期了，现在想了下刚开始排查这个问题的时候，其实搜索了网上触发到socketTimeout的错误堆栈的，自己本地没触发，但是根据网上的错误堆栈再看校验时间的地方，就一目了然了，还有一开始怀疑的方向错误了，总是以为配置的方式不对，漏了什么地方，其实是客户端一个隐藏配置引起的，官方文档又没有明确说明这个参数，实在是太坑了，谁知道配置超时时间小于1s还必须再配置一个selectInterval。
留言