背景
周一刚上班一个开发小哥火急火燎的过来找我,黑龙江某客户私有化环境的服务过一阵就报数据库连接失败,不知道是什么原因导致的,我以为是客户调整了网络,但是客户说并没有做任何调整,我使用ping测试也看不出什么问题,于是猜测是业务代码导致,我就问他最近是否有发布,他说上周的确发了一个版本,他也怀疑过是代码的问题,所以组织组内成员对发布的代码已经review了好几遍,并没有发现可疑点。
排查
[DruidPooledStatement.java:379] - CommunicationsException, druid version 1.2.8, jdbcUrl : jdbc:mysql://xxx:3306/db_xxx?useUnicode=true&characterEncoding=UTF-8&useOldAliasMetadataBehavior=true&useSSL=false&allowMultiQueries=true&rewriteBatchedStatements=true&serverTimezone=GMT%2B8&zeroDateTimeBehavior=convertToNull&autoReconnect=true, testWhileIdle true, idle millis 9950, minIdle 1, poolingCount 5, timeBetweenEvictionRunsMillis 60000, lastValidIdleMillis 9950, driver com.mysql.cj.jdbc.Driver, exceptionSorter com.alibaba.druid.pool.vendor.MySqlExceptionSorter 2024-11-05 10:35:19.671 [inter-listener-threadPool7] [] ERROR [DruidPooledStatement.java:379] - CommunicationsException, druid version 1.2.8, jdbcUrl : jdbc:mysql://xxx:3306/db_xxx?useUnicode=true&characterEncoding=UTF-8&useOldAliasMetadataBehavior=true&useSSL=false&allowMultiQueries=true&rewriteBatchedStatements=true&serverTimezone=GMT%2B8&zeroDateTimeBehavior=convertToNull&autoReconnect=true, testWhileIdle true, idle millis 8464, minIdle 1, poolingCount 5, timeBetweenEvictionRunsMillis 60000, lastValidIdleMillis 8464, driver com.mysql.cj.jdbc.Driver, exceptionSorter com.alibaba.druid.pool.vendor.MySqlExceptionSorter 2024-11-05 10:35:19.672 [inter-listener-threadPool7] [] ERROR [JdbcUtils.java:89] - close connection error java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
Communications link failure,多么熟悉的异常信息,老司机都知道这大概率就是网络问题,奈何找不到任何网络出问题的蛛丝马迹,所以尝试换个思路,从MySQL自身的日志碰碰运气,果不其然,MySQL的error日志中显示有条读取JSON的sql导致其退出,一起看下现场
复现
如我所料,只要执行日志中的sql就会让MySQL意外退出,紧接着重新启动,此时应用程序就会报Communications link failure,这条sql究竟有什么魔力居然可以让大名鼎鼎的MySQL瞬间崩塌,好奇心刹那涌上心头,接下来我们剥茧抽丝。
剥茧抽丝
从MySQL的日志中可以看到“This could be because you hit a bug”,怎么会呢?系统中对于JSON的操作语句很早就存在,如果是存在bug那早就暴露了,也不会等到今天,那会是什么原因呢?
从MySQL日志的错误栈可以看到大概是JSON解析失败了,过往经验告诉我引起JSON解析失败的原因无外乎格式不正确,那我就看下那行数据的extdata是否正确。
乍一看好像没啥问题,这本来也不是一个必填字段,空着就空着吧,其实不然,通过和其他数据对比,发现这其实是空串,并不是NULL,对NULL执行->>'$.'不会引起MySQL崩溃,而空串会。
到这也就可以解释“系统中对于JSON的操作语句很早就存在,如果是存在bug那早就暴露了,也不会等到今天才爆发,那会是什么原因呢?”,这次上线的代码对这个字段有写入空串的情况。
但是也引发我的另一个疑问,为什么其他环境没有问题?
我就不卖关子了,是因为其他环境的MySQL版本较高,这个环境使用的是5.7.20版本,我在翻看MySQL更新日志的时候发现5.7.22中确实提到修复了老版本的一个JSON函数导致MySQL退出的bug
遗憾的是“Bug #22253965”在网络上已经搜索不到具体的内容了,一位国外开发者针对这个bug为什么找不到的问题在MySQL论坛提出了讨论,也得到了回复,有兴趣的可以移步https://forums.mysql.com/read.php?10,667824,667824#msg-667824。
解决方案
升级,升级,升级。
事后思考
时刻关注软件的更新列表很重要,不要因为它的广泛使用就忽视升级,虽然升级过程可能像飞行中换引擎一样充满挑战,但这是让它保持最佳状态的关键步骤呢!
推荐阅读
https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-22.html#mysqld-5-7-22-bug