我们的分库分表中间件在线上运行了两年多，到目前为止还算稳定。在笔者将精力放在处理各种灾难性事件(例如中间件物理机宕机/数据库宕机/网络隔离等突发事件)时。竟然发现还有一些奇怪的corner case。现在就将排查思路写成文章分享出来。
Bug现场 应用拓扑应用通过中间件连后端多个数据库,sql会根据路由规则路由到指定的节点,如下图所示:
应用在做某些数据库操作时，会发现有比较大的概率失败。他们的代码逻辑是这样:
int count = updateSql(sql1); ... // 伪代码 int count = updateSql("update test set value =1 where id in ("100","200") and status = 1; if( 0 == count ){ throw new RuntimeException("更新失败"); } ...... int count = updateSql(sql3); ...即每做一次update之后都检查下是否更新成功，如果不成功则回滚并抛异常。
在实际测试的过程中，发现经常报错，更新为0。而实际那条sql确实是可以更新到的(即报错回滚后，我们手动执行sql可以执行并update count>0)。
笔者根据sql去中间件日志里面搜索。发现了非常奇怪的结果,日志如下:
2020-03-13 11:21:01:440 [NIOREACTOR-20-RW] frontIP=>ip1;sqlID=>12345678;rows=>0;sql=>update test set value =1 where id in ("1","2") and status = 1;start=>11:21:01:403;time=>24266; 2020-03-13 11:21:01:440 [NIOREACTOR-20-RW] frontIP=>ip1;sqlID=>12345678;rows=>2;sql=>update test set value =1 where id in ("1","2") and status = 1;start=>11:21:01:403;time=>24591;由于中间件对每条sql都标识了唯一的一个sqlID,在日志表现看来就好像sql执行了两遍!由于sql中有一个in，很容易想到是否被拆成了两条执行了。如下图所示:
这条思路很快被笔者否决了，因为笔者explain并手动执行了一下，这条sql确实只路由到了一个节点。真正完全否决掉这条思路的是笔者在日志里面还发现，同样的SQL会打印三遍！即看上去像执行了三次，这就和仅仅只in了两个id的sql在思路上相矛盾了。 数据库日志
那到底数据真正执行了多少条呢？找DBA去捞一下其中的sql日志，由于线下环境没有日志切割，日志量巨大，搜索时间太慢。没办法，就按照现有的数据进行分析吧。
日志如何被触发由于当前没有任何思路，于是笔者翻看中间件的代码,发现在update语句执行后,中间件会在收到mysql okay包后打印上述日志。如下图所示:
注意到所有出问题的update出问题的时候都是同一个NIOREACTOR线程先后打印了两条日志，所以笔者推断这两个okay大概率是同一个后端连接返回的。 什么情况会返回多个okay?
这个问题笔者思索了很久，因为在笔者的实际重新执行出问题的sql并debug时，永远只有一个okay返回。于是笔者联想到，我们中间件有个状态同步的部分,而这些状态同步是将set auto_commit=0等sql拼接到应用发送的sql前面。即变成如下所示:
sql可能为 set auto_commit=0;set charset=gbk;>update test set value =1 where id in ("1","2") and status = 1;于是笔者细细读了这部分的代码，发现处理的很好。其通过计算出前面拼接出的sql数量，再在接收okay包的时候进行递减，最后将真正执行的那条sql处理返回。其处理如下图所示:
但这里确给了笔者一个灵感，即一条sql文本确实是有可能返回多个okay包的。 真相大白
在笔者发现(sql1;sql2;)这样的拼接sql会返回多个okay包后，就立刻联想到，该不会业务自己写了这样的sql发给中间件，造成中间件的sql处理逻辑错乱吧。因为我们的中间件只有在对自己拼接(同步状态)的sql做处理，明显是无法处理应用传过来即为拼接sql的情况。
由于看上去有问题的那条sql并没有拼接，于是笔者凭借这条sql打印所在的reactor线程往上搜索，发现其上面真的有拼接sql!
如上图所示，(update1;update2)中update1的okay返回被驱动认为是所有的返回。然后应用立即发送了update3。前脚刚发送,update2的okay返回就回来了而其刚好是0，应用就报错了(要不是0，这个错乱逻辑还不会提前暴露)。那三条"重复执行"也很好解释了，就是之前的拼接sql会有三条。 为何是概率出现