一、现象

生产的3台ES用Nginx做代理，客户端->Nginx->ES都是长连接。ES客户端每天会有30条左右的超时日志，这是客户端设置了60s请求超时主动报错引起的，错误信息如下（搜索、按ID获取、建立索引都会出现超时）：

java.net.SocketTimeoutException: 60,000 milliseconds timeout on connection http-outgoing-922 [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.update(RestHighLevelClient.java:921)

客户端设置了socketTimeout为60秒，所以可以肯定的是请求长时间无数据返回导致报错。Nginx里的错误日志如下：

2021/05/20 13:26:58 [warn] 491406#491406: *94078113 an upstream response is buffered to a temporary file /data/openresty/nginx/proxy_temp/1/65/0000049651 while reading upstream, client: 10.81.127.209, server: 10.30.223.84, request: "POST /spprjm_customer/_search HTTP/1.1", upstream: "http://10.29.56.90:39200/spprjm_customer/_search", host: "10.30.223.84:86"
2021/05/20 13:26:59 [info] 491406#491406: *94076470 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while connecting to upstream, client: 10.45.179.90, server: 10.30.223.84, request: "POST /enterprise_v1/_search HTTP/1.1", upstream: "http://10.30.222.121:39200/enterprise_v1/_search", host: "10.30.223.84:86"

10.45.182.231 - - [21/Jun/2021:16:41:01 +0800] "POST /person_search_user_v1/_search HTTP/1.1" "/person_search_user_v1/_search" "60.052" "-" 499 0 "-" "Apache-HttpAsyncClient/4.1.4 (Java/1.8.0_144)"

这里的epoll_wait()错误与业务里的超时异常是一一对应的，就是说客户端等待60s后提前断开了长连接，于是Nginx也断开了与上游代理的长连接，最后响应499错误码。

二、排查问题

看到这些错误，于是在网络上寻找答案，下边列举几个感觉有价值的信息：

• 关于 Nginx 日志错误码 499的问题
• 谈nginx中的keepalive、Openresty主动关闭连接与KeepAlive，这两个讲解的是关于长连接请求的问题
• 、stackoverflow里关于ES客户端超时的提问，这两个讲解的是防火墙超时比tcp超时早导致的网络丢包问题
• linux下TCP参数设置详解、Nginx官方文档关于超时的设置
• 如何防止防火墙导致的数据库空闲连接断开问题，我们的客户端是90s长连接，用的时候会处理连接状态，不会报连接断开错误

通过排查服务器配置net.ipv4.tcp_keepalive_time = 1200可以排除是防火墙连接超时过早导致网络不通，一般防火墙连接超时是1小时（我没有找到任何教程对于这个时间的配置，但在 Iptables Default connections 里看到默认是600s超时，由于能力有限没办法得知服务器里的真实数值），TCP连接在1200s后会有多次探测，所以应该不是防火墙把连接过早断开的问题。

我把问题指向了ES服务，经过kibana里的监控得知，近期的请求延迟并不高，但是与客户端超时有一致的延迟突起，说明与ES还是有一定关系的，我找到，可以认为这里的监控值取的是平均值。那就把ES的慢请求日志打开，看看到底有多大的延迟，配置如下：

PUT /_all/_settings?preserve_existing=true
{
  "index.indexing.slowlog.level" : "info",
  "index.indexing.slowlog.source" : "1000",
  "index.indexing.slowlog.threshold.index.info" : "100ms",
  "index.search.slowlog.threshold.fetch.info" : "100ms",
  "index.search.slowlog.threshold.query.info" : "100ms"
}

经过几个小时的等待，生产最终有业务报超时了，然后排查ES慢日志，得到的最大延迟却只有1s左右（也有可能这个请求根本没打日志，这里还需要认真排查确认），看起来并不是ES响应慢的问题，到这里我没有了思路。

三、在测试环境复现问题

我本机开启多个线程对ES发起查询（客户端连接数配置充足，不然会停顿在获取连接的地方，反而复现不出请求超时），在线程数为50的时候下行带宽达到了100%，线程开到200时就开始频繁出现10s超时。使用jvisualvm查看线程状态发现，有大量线程长时间被挂起（带宽不够导致IO等待），线程唤醒后出现超时异常，但是Nginx的错误日志与生产的并不一样，因为生产只有epoll_wait()一种错误，测试环境却出现了如下几种错误，只有我强制关闭程序时才会出现与生产一致的错误：

2021/06/21 15:07:52 [info] 14749#0: *58644745 recv() failed (104: Connection reset by peer) while sending to client, client: 172.16.9.119, server: 172.16.1.78, request: "POST /prep_statistics_service_process_detail/_search HTTP/1.1", upstream: "http://172.16.1.78:9203/prep_statistics_service_process_detail/_search", host: "172.16.1.78:86"
2021/06/21 20:01:13 [info] 14749#0: *61424251 writev() failed (104: Connection reset by peer) while sending to client, client: 172.16.20.14, server: 172.16.1.78, request: "POST /prep_srms_service_record_group/_search HTTP/1.1", upstream: "http://172.16.1.78:9201/prep_srms_service_record_group/_search", host: "172.16.1.78:86"
2021/06/21 15:07:52 [info] 14749#0: *58658403 client 172.16.9.119 closed keepalive connection (104: Connection reset by peer)

经过思考，我认为可能是由于客户端线程挂起，而这时请求在Nginx这里是不停的读写的，客户端超时后，Nginx这里即有可能在读数据也有可能在写数据，最终出现这些网络错误。

于是我把测试程序放在网络更好的虚拟器上运行，但是CPU却在200线程时就占满了，最终500个线程只使用了50%的带宽，这时出现了我期待的5s超时。通过jvisualvm分析发现也是由于线程挂起导致，这次是CPU竞争导致的长时间等待。

于是我开始定位业务服务器的负载情况，通过观察历史监控数据得知GC停顿并不大，CPU负载也不高，出入带宽也才使用10%。分析到这里我没有了思路。不过今天测试组在做生产的搜索压测，导致近4个小时有100左右的业务60s请求超时日志，这又让我开始怀疑是ES负载高的问题。

总结：

• Nginx的 proxy_next_upstream 默认配置是：error timeout
• 生产配置的 proxy_connect_timeout 为3600秒是不合理的（客户端60s就会主动报错），这样就没法利用Nginx的重试机制
• 合理的配置应该设置: proxy_connect_timeout 10 快速触发超时并重连下一台机器，这样ES客户端很大几率不用等待60s就可正常通信