一、现象
okhttp调用某个服务,如果第二次访问间隔上一次访问时间超过60s,返回错误:"unexpected end of stream"。
二、最终定位原因:
空闲连接如果超过60秒,服务端会主动关闭连接。此时客户端恰巧访问了这个异常的连接,服务端返回RST错误连接标志位。
问题一:这个现象只要超过60秒就会复现吗?
答:不会,这个现象只会在TCP释放连接的四次挥手过程中出现。如果四次挥手结束了,客户端不会访问已关闭的连接。通过wireshark抓包,在测试环境,TCP四次挥手中的第一个FIN和第二个FIN间隔会有15毫秒到40毫秒不等。因此,碰到的概率不高,出现的机会不多。
问题二:为什么TCP释放过程中,客户端还可以使用该连接?
答:TCP连接是全双工的,服务端发完FIN,此时只是关闭了从服务到客户端的通道,客户端到服务端的通道依然是正常的。
问题三:为什么客户端在失败后没有重试?
答:项目组没有配置重试。
三、解决方案
1、okHttp增加守护线程,定时进行应用层心跳做探活。
2、调大服务端的关闭空闲长连接时间;
3、缩短客户端长连接的空闲清理时间,至少要小于服务端保持时间,且不可设置成一致,设置一致依然会出现问题。
四、具体排查过程
第一步:
思路:排查Server端日志,发现没有打出日志,首先推断出请求至少没走到Servlet应用层;
结论与解决措施:查询Web服务器Tomcat源码,查看长连接超时时间;
第二步:
思路:通过源码发现keepAliveTimeout(默认等于connectionTimeout)时间为60秒,此时已经和现象相符了,随后在开发测试环境测试改动该值。
结论与解决措施:在开发测试环境调小该值,然后使用netstat观察服务端的TCP连接状态,发现到了我们设置的时间,Established状态的TCP连接就会变成TIME_WAIT。
server: tomcat: keep-alive-timeout: 20s
第三步:
思路:上面知道了60秒会主动关闭,现在就要在本地复现一下,看看能否复现出问题,是不是每次都会出现问题。
结论与解决措施:客户端每隔60.008秒定时向客户端发送一个请求,并用wireshatk抓包,很快就复现出问题。
下面展示了在进行TCP挥手过程中,客户端(ip是75)访问服务端(ip是149),服务端返回一个RST。
如果超过61秒访问,现象不会出现,因为TCP连接已经完全关闭了,会重新建立连接,如下图,重新进行三次握手:
结论与解决措施:首先看客户端,客户端会在空闲一段时间,关闭某些空闲连接,项目组客户端设置了5分钟,时间过长,导致客户端一直没有检测。 不过客户端不会发心跳检测,只会定时关闭空闲连接。
然后,我让项目组查询生产服务端的keepalive时间,发现是7200s。
sysctl -a|grep keepalive_time net.ipv4.tcp_keepalive_time=7200 //TCP探活间隔2小时
第五步:
思路:在开发测试环境测试服务端的TCP连接,我们把开始测试环境改成空间连接30秒开始检测。
结论与解决措施:发现该配置不起作用。