MySQL中间件的连接错误问题排查
这是学习笔记的第 2020 篇文章
最近在对一个线上的分布式环境做高可用配置，在流程测试通过后，发现中间件中出现了大量的连接错误。
错误信息如下：
INFO | jvm 1 | 2019/06/25 08:53:35 | 2019-06-25 08:53:35,484 [ERROR][$_NIOREACTOR-3-RW] register err java.nio.channels.ClosedChannelException INFO | jvm 1 | 2019/06/25 08:53:35 | at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:257) INFO | jvm 1 | 2019/06/25 08:53:35 | at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:300) INFO | jvm 1 | 2019/06/25 08:53:35 | at io.mycat.net.NIOSocketWR.asynRead(NIOSocketWR.java:188) INFO | jvm 1 | 2019/06/25 08:53:35 | at io.mycat.net.AbstractConnection.asynRead(AbstractConnection.java:273) INFO | jvm 1 | 2019/06/25 08:53:35 | at io.mycat.net.FrontendConnection.register(FrontendConnection.java:444) INFO | jvm 1 | 2019/06/25 08:53:35 | at io.mycat.net.NIOReactor$RW.register(NIOReactor.java:160) INFO | jvm 1 | 2019/06/25 08:53:35 | at io.mycat.net.NIOReactor$RW.run(NIOReactor.java:92) INFO | jvm 1 | 2019/06/25 08:53:35 | at java.lang.Thread.run(Thread.java:748) INFO | jvm 1 | 2019/06/25 08:53:35 | (io.mycat.net.NIOReactor$RW:NIOReactor.java:163) INFO | jvm 1 | 2019/06/25 08:53:38 | 2019-06-25 08:53:38,892 [ERROR][$_NIOREACTOR-4-RW] register err java.nio.channels.ClosedChannelException
目前的技术栈架构是LVS+keepalived+MyCAT+MySQL,如下图所示：
对于这个问题的定位也算是比较曲折，最初是认为防火墙权限的问题，于是我做了如下的几个场景测试，结果大多数场景都失败了。
lvs防火墙 | 有错误日志 |
|---|---|
中间件防火墙 | 有错误日志 |
中间件到数据节点的防火墙 | 有错误日志 |
复制一个新的中间件，不配置lvs | 无错误日志 |
停止中间件节点的VIP配置 | 有错误日志 |
jdk安装包不够完整，重新安装 | 有错误日志 |
拷贝完整的目录，重新启动 | 有错误日志 |
最后得到了一个初步的结论：新配置的节点MyCAT可以正常启动，而已有的集群配置会出现问题，所以这个问题经过这样一系列测试，让人有些无奈。
当然也不是徒劳，经过这样一个过程之后，我和系统部的同事对这些服务器的其他配置做了对比，发现唯一的差别就是是否启用了LVS。
经过进一步的分析和确认，算是基本定位问题的位置了，那就是错误日志的输出格式比较规律，即每10秒钟会输出一批错误。按照这个规律我在lvs中进行检查，发现keepalived的配置确实有一个delay_loop的配置是10秒。顺着这个思路下去，发现对于RS的检测，这里使用的是TCP_CHECK的方式，而这种方式的连接注册对于MyCAT来说是不够友好的。在官网也找到了类似的错误说明，目前还没有很好的解决方式，而要更为优雅的解决，那就是使用TCP_CHECK之外的验证方式，这里推荐的就是MISC_CHECK（自定义脚本）的方式了。
RS的配置信息如下，在此我们定义了一个检查脚本，输出0或者1来进行状态校验。
配置信息如下：
real_server xx.124.140 8066 { weight 1 inhibit_on_failure # TCP_CHECK { # connect_timeout 1 # nb_get_retry 3 # delay_before_retry 1 # connect_port 8066 # } MISC_CHECK { misc_path "/etc/keepalived/scripts/mycat_check.sh xx.124.140 8066 tkgrowlog" misc_timeout 10 misc_dynamic } } real_server xx.124.142 8066 { weight 1 inhibit_on_failure # TCP_CHECK { # connect_timeout 1 # nb_get_retry 3 # delay_before_retry 1 # connect_port 8066 # } MISC_CHECK { misc_path "/etc/keepalived/scripts/mycat_check.sh xx.124.142 8066 tkgrowlog" misc_timeout 10 misc_dynamic }
而检测脚本的内容如下，根据轮询的机制，会输出日志到keepalived指定的目录下。
# cat mycat_check.sh #!/bin/bash result=`nc -v -z $1 $2` flag="succeeded" time=$(date "+%Y-%m-%d %H:%M:%S") if [[ $result =~ $flag ]] then echo "$time "$1:$2:$3": mycat is running..." >> /var/log/keepalived_check.log exit 0 else echo "$time "$1:$2:$3": mycat is not running..." >> /var/log/keepalived_check.log exit 1 fi
日志的输出如下：
2019-06-25 18:53:11 10.30.124.140:8066:testappdb: mycat is running... 2019-06-25 18:53:14 10.30.124.135:8064:testappdb: mycat is running... 2019-06-25 18:53:14 10.30.124.134:8064:testappdb: mycat is running... 2019-06-25 18:53:15 10.30.124.137:8065:testappdb: mycat is running... 2019-06-25 18:53:16 10.30.124.138:8065:testappdb: mycat is running... 2019-06-25 18:53:17 10.30.124.142:8066:testappdb: mycat is running...
按照目前的状态在下午的高可用测试中，前端业务几乎无感知。
高可用的测试大体包含如下的范围：
- 停止一个中间件节点，预期是对于业务无感知
- 停止两个中间件节点（一共两个），这时候业务连接失败，会在业务层转储生成日志信息，为后期的数据补录提供基础
- 关闭部分应用服务器节点的防火墙权限，短时间内没有变化，是因为这里使用的是长连接，而在一段时间之后，比如5-10分钟左右，会在业务层抛出错误
- 关闭MySQL节点，触发MHA切换，对于业务层有一定的影响，但是基于MHA高可用机制，业务会很快恢复。