诡异的druid链接池链接断开故障经验总结

背景

症状

排查

修复

背景

最近在陆续做机房升级相关工作，配合DBA对产线数据库链接方式做个调整，将原来直接链接读库的地址切换到统一的读负载均衡的代理haproxy上，方便机柜和服务器的搬迁。

切换之后线上时不时的会发生discard connection错误，导致程序报500错误，但不是每次都必现的。

开发框架: spring boot+mybatis+druid+shardingJDBC

网络架构:

appserver->mysql(master) 写

appserver->haproxy->mysql(slave)/n 读

第一反应肯定是因为这次的读库地址的变动引起的问题，觉得问题应该是druid链接池中的connection保活策略没起作用，只要做下配置修改应该就可以了。结果这个问题让我们排查了好几天，我们竟然踩到了千年难遇的深坑。

这个问题排查的很坎坷，一次次的吐血，最终我们定位到问题并且优雅的修复了，我们一起来体验下这个一次一次让你绝望一次一次打脸的过程。

症状

先说故障症状，经常出现如下错误：

The last packet successfully received from the server was 72,557 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.

根据错误日志初步判断肯定是与db之间的链接已经断开，尝试使用了一个已经断开的链接才会引起这个错误发生。但是根据我们对druid了解，druid有链接检查功能，按理不会拿到一个无效链接才对，带着这个线索我们上路了。

排查

为了准确的知道db的链接的存活时间，了解到haproxy对转发的db tcp链接空闲时间在1m之内，超过1m不活动就会被关掉。也就说我们与db之间的原来的长链接在1m之内会被断开。我们先不管这个时间设置的是否符合所有的大并发场景，至少在druid的链接池里会有有效链接检查，应该不会拿到无效链接才对，我们做了配置调整。

我们看下druid跟链接时间相关的配置：

配置的每项的意思这里就不解释了。

我们启用了testWhileIdle配置，让每次拿取链接的时候发起检查。根据timeBetweenEvictionRunsMillis的配置只有大于这个时间druid才会发起检查，所以可能的场景是拿到一个即将过期的链接，根据这个线索我们调整这个时间为20000ms，也就是超过20s会检查当前拿取的链接确定是否有效，检查的方式应该是使用validationQuery配置的sql语句才对，但是发现我们并找不到任何有关于SELECT 1的痕迹。

为什么你死活找不到 SELECT 1

首先要搞清楚validationQuery为什么没起作用，带着这个疑问开始debug druid源码。

闲置时间肯定会有大于timeBetweenEvictionRunsMillis时间的，会发起testConnectionInternal方法检查。我们继续跟进去看，

内部会使用validConnectionChecker检查对象发起检查。

debug 这里才发现，druid默认采用的是mysql.ping来做链接有效性检查。

druid 默认采用msyql.ping 协议检查

那是不是用msyql.ping协议并不会让mysql重新滑动session闲置时间，带着这个问题打开information_schema.processlist进程列表查看会不会刷新会话时间，通过 debug发现是会刷新时间的，说明没有问题，这条线索算是断了。

haproxy tiemout主动close上下游链接

调整方向，开始怀疑是不是haproxy的一些策略导致链接失效，开始初步怀疑haproxy的轮训转发后端链接是不是有相关会话保持方式，是不是我们配置有误导致haproxy的链接和mysql链接篡位了。

当然这个猜想有点夸张，但是没办法，技术人员就要有怀疑一切的态度。

为了还原产线的网络路线，我在本地搭了一个haproxy，了解下他的工作原理和配置，图方便我就用了yum顺手装了一个，版本是HA-Proxy version 1.5.18不知道是我本地环境问题还是这个版本的bug，我们配置的mode tcp活动检查一直不生效。

由于haproxy活动检查一直不通过，所以无法转发我的链接，搞了半天我只能手动装了一个低版本的haproxy HA-Proxy version 1.4.14。

完整的配置：

1.4的版本顺利完成活动检查。

我使用haproxy进行debug，调试下来也都没有问题，也翻了下haproxy如何转发链接的，内部通过会话的方式保持两个链接的关系，如果是tcp长链接应该不会出现什么问题。haproxy在http模式下有会话保持方式，tcp应该是直接捆绑的方式，一旦到timeout时间会主动close和mysql的链接，而且没有出现篡位的问题。到这里线索又断了。

自定义 ValidConnectionChecker 埋点日志

没有办法，只能试着埋点druid的检查日志，排查内部上一次的 check和报错之间的时间差和connectionId是不是一致的。

为了拿到connectionId只能反射获取，在本地debug下没问题，能正常拿到connectionId，但是发到验证环境进行验证的时候报错了，觉得奇怪，仔细看了下原来开发环境的配置和验证和生产的不一样，开发环境没有走读写分离。

验证和生产都是使用了mysql的replication的机制，所以导致我反射获取的代码报错。

通过debug发现，原来druid的connection是JDBC4Connection，变成了ReplicationConnection，而且里面包装了两个connection，一个masterconnection，一个slaveconnection，似乎问题有点浮现了。

通过debug发现druid的检查还是会正常走到，当走到ReplicationConnection内部的时候ReplicationConnection有一个currentConnection，这个链接是会在masterConnection和slaveConnection之间切换，切换的依据是readOnly参数。

在检查的时候由于druid并不感知上层的参数，readOnly也就不会设置。所以走的是masterConnection，但是在程序里用的时候通过spring的TransactionManager将readOnly传播到了ShardingJDBC，ShardingJDBC在设置到ReplicationConnection上，最后导致真正在使用的时候其实使用的是slaveConnection。

找到这个问题之后去druid github Issues搜索了下果然有人提过这个问题，在高版本的druid中已经修复这个问题了。

修复

修复这个问题有两个方法，第一个方法，建议升级 druid，里面已经有MySqlReplicationValidConnectionChecker检查器专门用来解决这个问题。第二个方法就是自己实现ValidConnectionChecker检查器，但是会有在将来出现bug的可能性。

由于时间关系文章只讲了主要的排查路线，事实上我们陆续花了一周多时间，再加上周末连续趴上十几个小时才找到这根本问题。

这个问题之所以难定位的原因主要是牵扯的东西太多，框架层面、网络链接层面、mysql服务器层面，haproxy代理等等，当然其中也绕了很多弯路。。

下面分享在这个整个排查过程中的一些技术收获。

相关技术问题

1.mysqlConenction提供了ping方法用来做活动检查，默认MySqlValidConnectionChecker使用的是pinginternal。

2.低版本的druid不支持自定义 ValidConnectionChecker 来做个性化的检查。

3.druid 的test方法使用注意事项，testOnBorrow 在获取链接的时候进行检查，与testWhileIdle是护持关系。

3.kill mysql processlist 进程会话到链接端tcp状态有延迟，这是tcp的四次断开延迟。

4.haproxy 1.5.18 版本 mode tcp check不执行，健康检查设置无效。

5.mysql replication connection master/slave切换逻辑需要注意，会不会跟上下油的链接池组合使用出现bug，尤其是分库不表、读写分离、自定义分片。

6.排查mysql服务器的问题时，打开各种日志，操作日志，binlog日志。

7.springtransactionmanagenent 事务传播特性会影响下游数据源的选择，setreadonly、setautocommit。

8.低版本的 druid MySqlValidConnectionChecker 永远执行不到 ReplicationConnection ping 方法。

作者：王清培(沪江网资深架构师)