有客户反馈控制台业务无法正常使用,上线排查日志发现数据库连接异常,捞取日志发现最早出现问题的时间是上午11点左右就已经存在报错

服务器截图
服务器截图

排查

数据库使用了Atlas中间件,我先查看了atlas机器的连接情况,发现,存在大量的CLOSE_WAIT连接

[root@xxxx50 conf]# netstat -na|grep xxxx1
tcp        1      0 1xx.xxx.xxx.xxx:xxxx1        xxx.xxx.xx.79:xxxx        CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:60980             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:29749             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:56051             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:32461             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:58653             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:31756             CLOSE_WAIT 
tcp       96      0 127.0.0.1:xxxx1             127.0.0.1:48699             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:63649             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:37318             CLOSE_WAIT 
tcp       96      0 127.0.0.1:xxxx1             127.0.0.1:61404             CLOSE_WAIT 
tcp        1      0 1xx.xxx.xx.x50:xxxx1        1xx.xxx.xx.58:5xxx7         CLOSE_WAIT 
tcp        1      0 1xx.xxx.xx.x50:xxxx1        1xx.xxx.xx.62:6xxx3         CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:59872             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:64986             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:25126             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:48896             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:38281             CLOSE_WAIT 
tcp        1      0 1xx.xxx.xx.x50:xxxx1        xx.xx.xx.50:56473          CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:63201             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:29351             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:42259             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:42395             CLOSE_WAIT 
tcp       86      0 127.0.0.1:xxxx1             127.0.0.1:37322             CLOSE_WAIT 
......省略几百个

//替代命令 netstat -na| grep xxxx1 | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'

简单复习一下TCP三次握手,四次挥手可以知道,这时候应该是atlas服务端无法发出FIN的关闭连接请求导致一直卡在CLOSE_WAIT状态,为了验证是不是因为CLOSE_WAIT导致数据库查询出现问题,让测试用jmeter对备机发起并发查询,在发起几百次请求后发现备机也复现了上述在主机的问题。

清理了CLOSE_WAIT的请求后,备机请求恢复正常。看起来原因找到了,是因为atlas不执行第三次挥手导致大量TCP请求占用句柄导致数据库连接出现问题。

但是根本原因是什么数据库操作触发了atlas的隐藏bug,这个暂时无法找到,我们在清理之后,发现所有请求都回到正轨,没有再出现卡在CLOSE_WAIT的连接。

解决方案

这应该是atlas的一个隐藏BUG,但是现在该团队已经停止维护,所以在根本原因是无法解决,建议停止使用以防触发BUG,如果非要使用,可以起定时任务定时清理CLOSE_WAIT的任务。

课外阅读

https://mp.weixin.qq.com/s?__biz=MzI4MjA4ODU0Ng==&mid=402163560&idx=1&sn=5269044286ce1d142cca1b5fed3efab1&3rd=MzA3MDU4NTYzMw==&scene=6#rd

https://juejin.cn/post/6844903734300901390

命令行

https://www.cnblogs.com/ggjucheng/archive/2012/01/14/2322659.html

https://www.jianshu.com/p/df62ac76ec5b

https://www.cnblogs.com/ggjucheng/archive/2012/01/08/2316661.HTML