dbcp mysql偶然丢包_一次 MySQL 及 Redis 灵异断连现象：安全组静默丢包解决办法

一次 MySQL 及 Redis 灵异断连现象：安全组静默丢包解决办法时间：2019-03-11 10:41    浏览次数:

发布者:武汉润天教育    来源:武汉金信润天

0

差不多一两年前，在阿里云上遇到一个奇怪的 Redis 连接问题，每隔十来分钟，服务里的 Redis client 库就报告连接 Redis server 超时，当时花了很大功夫，发现是阿里云会断开长时间闲置的 TCP 连接，不给两头发 FIN or RST 包。

作者：纤夫张来源：知乎|2019-03-06 10:36 收藏  分享

一、引子：Redis client library 连接 Redis server 超时

差不多一两年前，在阿里云上遇到一个奇怪的 Redis 连接问题，每隔十来分钟，服务里的 Redis client 库就报告连接 Redis server 超时，当时花了很大功夫，发现是阿里云会断开长时间闲置的 TCP 连接，不给两头发 FIN or RST 包。当时我们的 Redis server 没有打开 tcp_keepalive 选项， Redis server 侧那个连接还存在于 Linux conntrack table 里，而 Redis client 侧由于连接池重用连接进行 get、set 发现连接坏掉就关闭了，所以 client 侧的对应 local port 回收了。

当接下来 Redis 重用这个 local port 向 Redis server 发起连接时，由于 Redis server 侧的 conntrack table 里四元组对应状态是 ESTABLISHED，所以自然客户端发来的 TCP SYN packet 被丢弃，Redis client 看到的现象就是连接超时。

解决这个问题很简单，打开 Redis server 的 tcp_keepalive 选项就行。 然而当时没想到这个问题深层次的原因影响很重大，后果很严重!

二、孽债：”SELECT 1” 触发的 jdbc4.CommunicationsException

最近生产环境的 Java 服务几乎每分钟都报告类似下面这种错误：

[main] ERROR jdbc.audit - 2. Statement.execute(select 1) select 1

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 576,539 milliseconds ago.  The last packet sent successfully to the server was 5 milliseconds ago.

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

at java.lang.reflect.Constructor.newInstance(Constructor.java:423)

at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)

at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:990)

at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)

at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2480)

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2438)

at com.mysql.jdbc.StatementImpl.executeInternal(StatementImpl.java:845)

at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:745)

at net.sf.log4jdbc.StatementSpy.execute(StatementSpy.java:842)

at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:158)

at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:172)

at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148)

at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)

at cn.yingmi.hikari.Main.main(Main.java:30)

Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.

at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)

at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)

... 14 more

由于有之前调查 Redis 连接被阿里云异常中断的先例，所以怀疑是类似问题，花了大量时间比对客户端和服务端的 conntrack table，然而并没有引子中描述的问题。

后来又去比对多个 MySQL 服务器的 sysctl 设置，研究 iptables TRACE，研究 tcpdump 抓到的报文，试验 tw_reuse, tw_recyle 等参数，调整 Aliyun 负载均衡器后面挂载的 MySQL 服务器个数，都没效果。

反而意外发现一个新问题，在用如下命令不经过阿里云 SLB 直接连接数据库时，有的数据库可以在 600s 时返回，有的则客户端一直挂着，半个多小时了都退不出来，按 ctrl-c 中断都不行。

mysql -h mysql-server-ip -u mysql-user -p -e 'SELECT sleep(1000)'

当时检查了一个正常的数据库和一个不正常的数据库，发现两者的 wait_timeout 和 interactive_timeout 都是 600s，思索良苦，没明白怎么回事，然后偶然发现另外一个数据库的 wait_timeout=60s，却一下子明白了原始的 “select 1” 问题怎么回事。

我们的服务使用了 Hikari JDBC 连接池，它的 idleTimeout 默认是 600s, maxLifetime 默认是 1800s，前者表示 idle JDBC connection 数量超过 minimumIdle 数目并且闲置时间超过 idleTimeout 则关闭此 idle connection，后者表示连接池里的 connection 其生存时间不能超过 maxLifetime，到点了会被关掉。

在发现 “select 1” 问题后，我们以为是这俩参数比数据库的 wait_timeout=600s 大的缘故，所以把这两个参数缩小了，idleTimeout=570s, maxLifetime=585s，并且设置了 minimumIdle=5。

但这两个时间设置依然大于其中一个数据库失误设置的 wait_timeout=60s，所以闲置连接在 60s 后被 MySQL server 主动关闭，而 JDBC 并没有什么事件触发回调机制去关闭 JDBC connection，时间上也不够 Hikari 触发 idleTimeout 和 maxLifetime 清理逻辑，所以 Hikari 拿着这个“已经关闭”的连接，发了 “select 1” SQL 给服务器检查连接有效性，于是触发了上面的异常。

解决办法很简单，把那个错误配置的数据库里 wait_timeout 从 60s 修正成 600s 就行了。

下面继续讲述 “SELECT sleep(1000)” 会挂住退不出来的问题。

三、缘起：阿里云安全组与 TCP KeepAlive

最近看了一点佛教常识，对”诸法由因缘而起“的缘起论很是感慨，在调查 “SELECT sleep(1000)” 问题中，真实感受到了“由因缘而起” 的意思