记一次线上CLOSE_WAIT事件

2020年3月5号14时40分,技术支持反馈有用户来电询问单据无法打印,开发人员经过日志排查,发现是连接阿里云OSS超时,经过日志分析,从3月4号16时10分开始陆陆续续出现单据打印失败,因为昨天前天均未发版,上次发版还是2月28号,因此不太可能是近期发版导致的问题。
连接超时,首先想到的是联系运维架构组是否有何种外网访问限制或者OSS固有问题,但是均无答案。包括开通外网访问限制均未能解决问题。
接着,开发人员说去年也遇到过类似的问题,是连接池占满了,重启之后解决,但是后续压测均未能定位到原因。因此我们也紧急重启了一台机器,另一台dump之后也重启了,果然问题解决,单据正常打印。
接着查看句柄信息,发现有大量的TIME_WAIT状态的TCP连接,共计256条,因此考虑是连接未正常释放,翻看代码,果然,确实是一行重复请求OSS的代码,初步断定是该原因导致。
记一次线上CLOSE_WAIT事件
晚上通过压测,发现伴随着每一次打印请求都会出现一条TIME_WAIT状态的TCP连接,循环请求200多次之后,果然出现了连接超时的错误日志。删除重复代码,重新启动程序,保持跟之前相同的重复请求,300次之后,程序正常,无连接超时的错误日志,通过lsof -p pid 查看句柄,也未发现处于TIME_WAIT状态的TCP连接,OK原因定位。
修改代码,申请发版,观察线上也未出现异常状态的TCP连接。
再来回看原因,OSS服务器数据发送完成之后向应用服务器(OSS JDK)发送了SEQ+FIN报文请求终止连接(此时OSS服务器状态FIN_WAIT_1),应用服务器很快回复了ACK(应用服务器CLOSE_WAIT,OSS FIN_WAIT_2),但是因为应用服务端代码没有正常关闭连接,导致无法发送SEQ+FIN报文给OSS服务器,应用服务器使用的OSS JDK连接池大小是256,256次请求之后,连接池占满,后续请求无法获取到连接,10秒超时。

记一次线上CLOSE_WAIT事件