ES客户端异常关闭原因
一、问题描述
新测试环境的icedoc有个2分钟触发一次的定时任务，任务里有查询ES逻辑，在启动后不久（10分钟以上）开始出现ES客户端异常关闭的错误：
1.1、先出现客户端连接异常关闭的错误
2021-07-02 10:34:00.600 ERROR c.s.a.s.i.SearchServiceImpl
org.apache.http.ConnectionClosedException: Connection closed unexpectedly
at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:813)
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.search(RestHighLevelClient.java:970)
1.2、紧接着I/O dispatch线程异常退出
2021-07-02 10:34:00.709 ERROR o.a.h.i.n.c.CloseableHttpAsyncClientBase$1 [run:66] [pool-1-thread-1] []
- I/O reactor terminated abnormally
org.apache.http.nio.reactor.IOReactorException: I/O dispatch worker terminated abnormally
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:359)
at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:221)
at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NoSuchMethodError: org.apache.http.ConnectionClosedException: method <init>()V not found
at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.endOfInput(HttpAsyncRequestExecutor.java:356)
at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:261)
at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:81)
at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:39)
at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:114)
at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:162)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:337)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:276)
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)
1.3、后续每2分钟的任务执行都是I/O reactor已停止的错误
2021-07-02 10:36:00.633 ERROR c.s.c.f.ServiceExceptionFiler
java.lang.RuntimeException: Request cannot be executed; I/O reactor status: STOPPED
at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:831)
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.search(RestHighLevelClient.java:970)
调整定时触发频率为1小时，没有再发现连接异常关闭的错误了。由于其他环境都是1小时的频率，所以也没有发现这种错误
二、复现问题
2.1、在开发环境按1分钟执行一次，重复执行了1天时间，只出现一次连接中止，但并未影响后续请求
2021-07-22 00:25:44.662 ERROR c.s.a.s.i.SearchServiceImpl [search:235] [DubboServerHandler-172.16.20.14:21027-thread-200] []
java.io.IOException: 您的主机中的软件中止了一个已建立的连接。
at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:828)
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.search(RestHighLevelClient.java:970)
2.2、通过-Xmx64m调整JVM堆内存后出现GC检查的异常，并复现了后续连接异常关闭的错误
2021-07-22 10:39:50.324 WARN o.a.z.ClientCnxn$SendThread [run:1162] [main-SendThread(172.16.2.55:2181)] []
- Session 0x104d4b207c30562 for server 172.16.2.55/172.16.2.55:2181, unexpected error, closing socket connection and attempting reconnect
java.lang.OutOfMemoryError: GC overhead limit exceeded
at org.apache.zookeeper.ClientCnxn$SendThread.sendPing(ClientCnxn.java:973)
at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1118)
2021-07-22 10:39:50.526 ERROR c.s.c.f.ServiceExceptionFiler [afterThrowing:64] [DubboServerHandler-172.16.20.14:21027-thread-22] []
- SearchResponse com.worley.api.service.impl.SearchServiceImpl.search(SearchRequest)
java.lang.OutOfMemoryError: GC overhead limit exceeded
at com.fasterxml.jackson.core.json.ByteSourceJsonBootstrapper.constructParser(ByteSourceJsonBootstrapper.java:254)
at com.fasterxml.jackson.core.JsonFactory._createParser(JsonFactory.java:1322)
at com.fasterxml.jackson.core.JsonFactory.createParser(JsonFactory.java:827)
at org.elasticsearch.common.xcontent.json.JsonXContent.createParser(JsonXContent.java:91)
at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:142)
at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:114)
at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:90)
at org.elasticsearch.search.lookup.SourceLookup.sourceAsMapAndType(SourceLookup.java:86)
at org.elasticsearch.search.lookup.SourceLookup.sourceAsMap(SourceLookup.java:90)
at org.elasticsearch.search.SearchHit.getSourceAsMap(SearchHit.java:412)
at com.worley.api.service.impl.SearchServiceImpl.search(SearchServiceImpl.java:250)
2021-07-22 10:39:51.869 INFO o.a.z.ClientCnxn$SendThread [logStartConnect:1032] [main-SendThread(172.16.2.55:2181)] []
- Opening socket connection to server 172.16.2.55/172.16.2.55:2181. Will not attempt to authenticate using SASL (unknown error)
2021-07-22 10:39:51.991 INFO o.a.z.ClientCnxn$SendThread [primeConnection:876] [main-SendThread(172.16.2.55:2181)] []
- Socket connection established to 172.16.2.55/172.16.2.55:2181, initiating session
2021-07-22 10:39:52.115 INFO o.a.z.ClientCnxn$SendThread [onConnected:1299] [main-SendThread(172.16.2.55:2181)] []
- Session establishment complete on server 172.16.2.55/172.16.2.55:2181, sessionid = 0x104d4b207c30562, negotiated timeout = 30000
2021-07-22 10:41:47.954 ERROR c.s.a.s.i.SearchServiceImpl [search:235] [DubboServerHandler-172.16.20.14:21027-thread-23] []
org.apache.http.ConnectionClosedException: Connection closed unexpectedly
at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:813)
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.search(RestHighLevelClient.java:970)
at com.worley.api.service.impl.SearchServiceImpl.search(SearchServiceImpl.java:228)
2.3、在控制台看到了几处系统ERR的信息并没有打印在日志文件里
通过查看新测试环境启动命令，发现堆内存配置是
-Xms256m -Xmx512m，在加上每2分钟触发一次任务，有可能是内存不足导致连接未正常退出。
但是一般这种错误会抛出业务层并打印在日志文件里，在新测试环境未发现GC的日志
2021-07-22 12:46:56.597 INFO
Exception in thread "pool-1-thread-1" java.lang.OutOfMemoryError: GC overhead limit exceeded
at java.util.HashMap$KeySet.iterator(HashMap.java:916)
at java.util.HashSet.iterator(HashSet.java:172)
at java.util.Collections$UnmodifiableCollection$1.<init>(Collections.java:1039)
at java.util.Collections$UnmodifiableCollection.iterator(Collections.java:1038)
at org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processTimeouts(DefaultConnectingIOReactor.java:204)
at org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.processEvents(DefaultConnectingIOReactor.java:158)
at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:351)
at org.apache.http.impl.nio.conn.PoolingNHttpClientConnectionManager.execute(PoolingNHttpClientConnectionManager.java:221)
at org.apache.http.impl.nio.client.CloseableHttpAsyncClientBase$1.run(CloseableHttpAsyncClientBase.java:64)
at java.lang.Thread.run(Thread.java:748)
# 这里在控制台的ERR打印的，所以日志文件里找不到
Exception in thread "RMI TCP Connection(idle)" java.lang.OutOfMemoryError: GC overhead limit exceeded
Exception in thread "I/O dispatcher 2" Exception in thread "RMI TCP Connection(idle)" java.lang.OutOfMemoryError: GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
Exception in thread "pool-1-thread-1" java.lang.OutOfMemoryError: GC overhead limit exceeded
# 日志文件里找到了关于GC的错误日志，说明新测试的iecdoc不是GC问题引起的
2021-07-22 14:40:15.802 ERROR c.s.c.f.ServiceExceptionFiler [afterThrowing:64] [DubboServerHandler-172.16.20.14:21027-thread-39] []
- SearchResult com.worley.ecdoc.service.index.ecdoc.EcdocContentIndexSearchService.cmsPublishListSearch(EcdocContentSearchVO)
java.lang.OutOfMemoryError: GC overhead limit exceeded
2.4、使用与新测试一样的频率(2分钟)重复调用，在40分钟后出现一样的错误，问题完整复现
由于nginx长连接超时配置为120s，客户端1.0.3版本未设置长连接保持时间，全部依赖nginx的配置。
我怀疑是客户端恰好在nginx即将断开长连接的时候拿到连接，在请求时nginx正好关闭长连接导致这个错误。
这里有个错误需要明确指出:
java.lang.NoSuchMethodError: org.apache.http.ConnectionClosedException: method <init>()V not found
这是由于在httpcore-nio-4.4.12的org.apache.http.nio.protocol.HttpAsyncRequestExecutor.endOfInput方法里使用无参构造器实例化ConnectionClosedException时报错导致的，
因为httpcore-4.4.6里没有这个无参构造器，高版本里才有
@Override
public void endOfInput(final NHttpClientConnection conn) throws IOException {
final State state = getState(conn);
final HttpContext context = conn.getContext();
synchronized (context) {
if (state != null) {
if (state.getRequestState().compareTo(MessageState.READY) != 0) {
state.invalidate();
}
final HttpAsyncClientExchangeHandler handler = getHandler(conn);
if (handler != null) {
if (state.isValid()) {
handler.inputTerminated();
} else {
// 从错误日志里可以看到，用无参构造器实例化 ConnectionClosedException 失败
handler.failed(new ConnectionClosedException());
}
}
}
if (conn.getSocketTimeout() <= 0) {
conn.setSocketTimeout(1000);
}
conn.close();
}
}
最终出现I/O reactor terminated abnormally错误，导致后续请求一直报Request cannot be executed; I/O reactor status: STOPPED的错误:
public CloseableHttpAsyncClientBase(
final NHttpClientConnectionManager connmgr,
final ThreadFactory threadFactory,
final NHttpClientEventHandler handler) {
super();
this.connmgr = connmgr;
if (threadFactory != null && handler != null) {
this.reactorThread = threadFactory.newThread(new Runnable() {
@Override
public void run() {
try {
final IOEventDispatch ioEventDispatch = new InternalIODispatch(handler);
connmgr.execute(ioEventDispatch);
} catch (final Exception ex) {
log.error("I/O reactor terminated abnormally", ex);
} finally {
status.set(Status.STOPPED); // 异常后设置了状态为：STOPPED
}
}
});
} else {
this.reactorThread = null;
}
this.status = new AtomicReference<Status>(Status.INACTIVE);
}
2.5、使用与新测试一样的频率(2分钟)重复调用，调整httpcore-core-4.4.12的依赖
在iecdoc里调整版本
<dependency>
<groupId>org.apache.httpcomponents</groupId>
<artifactId>httpcore</artifactId>
<version>4.4.12</version>
</dependency>
使用debug启动，并在endOfInput里设置断点。等待20分钟后端点被触发，通过单步执行走到handler.failed(new ConnectionClosedException())这行代码，这次没有类构造失败的错误了，
只是报了下列Connection is closed的错误，后续请求正常执行，说明只要I/O dispatch线程正常就可以继续获取连接发起请求：
2021-07-23 14:44:26.804 ERROR c.s.a.s.i.SearchServiceImpl [search:235] [DubboServerHandler-172.16.20.14:21027-thread-88] []
- search error:
org.apache.http.ConnectionClosedException: Connection is closed
at org.elasticsearch.client.RestClient.extractAndWrapCause(RestClient.java:813)
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.search(RestHighLevelClient.java:970)
at com.worley.api.service.impl.SearchServiceImpl.search(SearchServiceImpl.java:228)
这个异常只是影响当前请求，可以使用spring-retry包的重试机制解决。
三、总结
导致Request cannot be executed; I/O reactor status: STOPPED的错误是由于I/O dispatch线程异常退出导致
- 唯一原因是
ConnectionClosedException的构造错误引起（httpcore-4.4.6版本过低）
导致程序在endOfInput方法里判断连接状态是无效的原因，目前发现有两种：
- 堆内存不足
GC overhead limit exceeded导致连接关闭 - 由于客户端长连接未设置，完全依赖服务端主动关闭长连接。在获取请求后，此时服务端有可能主动（达到设置的过期时间）关闭长连接。
解决方式：
- 客户端设置长连接时间小于服务端，有效避免客户端发起请求前服务端突然断开长连接
