图片来自Pexels说实话，这是一个比较曲折的bug追踪之旅。10月28日，我们在GitHub上提交了一个issue，但由于官方开发者的主观臆断，两次被关闭。直到11月20日才确定为bug并发布修复版，历时20多天。本文将还原bug分析过程，提炼宝贵的经验和技术点。通过本文，您将获得：排查思路数据库中间件ShardingProxy原理MySQL预编译过程及交互协议Wireshark抓包分析MySQL的奇葩技巧问题描述此bug来自我代表公司的读者预研ShardingProxy（aShardingSphere的子产品，可以做分库分表，后面会详细介绍）。他按照官方文档写了一个很简单的demo，但是运行后无法查询到数据。以下是他遇到问题后发给我的信息。希望能帮助定位原因：截图中的doc详细记录了ShardingProxy的配置、调试分析日志，以及问题的具体现象。为了方便大家理解，我重新描述一下这个Demo的业务逻辑和问题外观。从demo的业务逻辑可以看出，这个demo非常简单，主要是跑通ShardingProxy的分库分表功能。程序使用SpringBoot+MyBatis来实现单表的查询逻辑，然后使用这个表的一个long字段作为partitionkey，通过ShardingProxy进行分表。下面是那个数据表的详细定义，一共有16个字段。可以关注前两个字段。其他字段与本文提到的bug无关。前两个字段的作用如下：BIZ_DT：业务字段，日期类型，与bug相关ECIF_CUST_NO：bigint类型，用作分区键代码是Controller调用Service，Service调用Dao，Dao是通过MyBatis实现的，所以我这里就不贴了。由于使用了ShardingProxy中间件，与直连数据库的配置会有所不同。定义dataSource时，url需要这样配置：jdbc:mysql://127.0.0.1:3307/sharding_db?useServerPrepStmts=true&cachePrepStmts=true&serverTimezone=UTC可以看出jdbc连接的是逻辑数据源sharding_dbShardingProxy，端口是3307，不是真正的底层数据库和MySQLServer真正的3306端口。下面介绍具体原理。其中，蓝色标记的两个参数useServerPrepStmts和cachePrepStmts，与本文提到的bug有关。这里先提一下，后面再分析。另外，ShardingProxy的分表策略是：使用long类型的ecif_cust_no字段对2取模分两表。具体配置如下：shardingColumn:ecif_cust_noalgorithmExpression:pscst_prdt_cvr${ecif_cust_no%2}问题描述先说一下遇到的问题。首先在数据表中预插入一条ECIF_CUST_NO等于10000的数据：然后启动demo程序，使用curl发起post请求，查询ecifCustNo等于10000的记录，查不到数据：至此，背景基本解释清楚了，为什么数据库里明明有数据，程序却找不到呢？ShardingProxy的问题还是应用本身的问题？ShardingProxy原理介绍在开始这个问题的分析过程之前，我先快速科普一下ShardingProxy的基本原理，让大家能够更好的理解我的分析思路。你一定接触过开源数据库中间件，最流行的是MyCat和ShardingSphere。其中MyCat由阿里开源；ShardingSphere由当当网开源，在京东逐步发展，2020年成为Apache顶级项目。ShardingSphere的目标是一个生态系统，它由三个独立的产品组成：ShardingJDBC、ShardingProxy和ShardingSidecar。本文重点介绍ShardingProxy的普及，其他两篇不再展开。什么是ShardingProxy？ShardingProxy属于MyCat的对标产品。它被定位为一个透明的数据库代理。可以理解为：一个实现MySQL协议的Server（独立进程），可用于读写分离，分库分表，灵活事务。静待现场。对于应用程序或者DBA来说，ShardingProxy可以作为数据库代理，可以直接使用MySQL客户端工具（Navicat）或者命令行与其进行交互。在内部，ShardingProxy通过MySQL原生协议与真正的MySQL服务器通信。图1：ShardingProxy应用架构图从架构图上看，ShardingProxy相当于MySQL，本身不存储数据，只是对外屏蔽了Database的存储细节。您可以像连接MySQL一样连接ShardingProxy（端口不同除外），配合您熟悉的ORMapping框架使用。ShardingProxy的内部架构我们先来看看ShardingProxy的内部架构，后续的源码分析中会涉及到。图2：ShardingProxy内部架构图整个架构分为前端、核心组件和后端：前端（Frontend）：负责与客户端的网络通信，使用NIO框架，完成编译MySQL协议在通信过程中的解码。Core-module：得到解码后的MySQL命令后，开始调用Sharding-Core进行SQL的解析、改写、路由、合并等核心功能。Backend：与真实数据库交互，使用Hikari连接池，同样涉及到MySQL协议的编解码。ShardingProxy的预编译SQL功能本文的bug与ShardingProxy的预编译SQL有关。这里我们将分别介绍该功能和相关的MySQL协议。这是本文的关键。请耐心阅读。熟悉数据库开发的同学一定知道：预编译SQL（PreparedStatement），在数据库中接收一条SQL并执行。一般分为以下三个步骤：词法语义分析优化SQL，制定执行计划执行并返回结果但是，在很多情况下，一个SQL语句可能会被重复执行，但是执行过程中的参数值不同的。预编译函数用占位符替换这些值，最终达到一次编译多次运行的效果，省去了解析和优化，大大提高了SQL的执行效率。假设我们要执行以下SQL两次：SELECT*FROMt_userWHEREuser_id=10;那么JDBC和MySQL之间的协议消息如下：通过上面的过程，我们可以看到：第一条消息是PreparedStatement，将查询语句中的参数值替换为问号，告诉MySQL预编译这条SQL。消息2MySQL告诉JDBC准备成功。第3条消息JDBC设置参数为1。消息4MySQL返回查询结果。第5条和第6条消息表示第二次执行相同的SQL，不需要再次预编译。回到ShardingProxy，如果需要支持预编译功能，交互流程就得改，因为Proxy收到JDBCPreparedStatement命令时，SQL中的shardingkey是一个问号，不知道是哪个realdatabase路由到.于是，流程就变成了这样：可以看出，Proxy在收到PreparedStatement命令后，并没有将这条消息转发给MySQL，只是缓存了SQL。收到ExecuteStatement命令后，通过partitionkey和传递的参数值来确定真正的数据库，并与MySQL进行交互。问题分析上一章基本上把这个bug相关的原理和知识都介绍清楚了，下面正式进入问题分析流程。刚开始收到这个问题的时候，我也是比较秃的，尤其是看到下面的读者留言的时候。当然，我的功力还达不到瞎猜的程度，我来说说我的完整思路吧。第一步：为了重现问题，我请读者将Demo、数据库脚本和ShardingProxy配置的源码打包发给我，然后在本地安装ShardingProxy4.1.1，然后通过Navicat连接到ShardingProxy执行数据库脚本。环境基本就绪了。启动Demo程序，通过Postman发送请求后，问题稳定重现，确实找不到数据。第二步：确认应用是否存在bug。因为整个代码非常简单，代码层面唯一可能出问题的就是Mybatis层。为了证实这一点，我修改了SpringBoot的配置，打印了MyBatis的调试日志。再次发起请求后，可以在控制台看到如下详细日志：日志中没有发现异常，PreparedStatement和ExecuteStatement参数设置正确，查询结果确实为空。为了缩小排查范围，我将dataSource的配置改回直接连接真实数据库，这样可以排除ShardingProxy的干扰因素。修改后的url如下：jdbc:mysql://127.0.0.1:3306/db1?useServerPrepStmts=true&cachePrepStmts=true&serverTimezone=UTC其中db1是真正的数据库，3306也是MySQL服务器的端口。然后再次使用Postman发送请求，可以看到返回了正确的数据。通过这一步，我再次将疑似对象转移到ShardingProxy，将dataSource配置改回原来的，继续排查。第三步：ShardingProxy故障排除首先查看ShardingProxy的运行日志，没有发现异常；其次可以看到日志中的ActualSQL是正确的，已经根据partitionkey:[INFO]17:25:48.804[ShardingSphere-Command-15]ShardingSphere-SQL-正确路由到了pcsct_prdt_cvr0表ActualSQL:ds_0:::SELECTBIZ_DT,ECIF_CUST_NO,DEP_FLG...FROMpscst_prdt_cvr0WHEREECIF_CUST_NO=?:::[10000]因此可以推断，ShardingProxy的分库分表配置应该没有问题。我开始怀疑：是不是和ShardingProxy使用的数据库驱动有关？因为这个Jar包是应用端选择的版本，手动放在ShardingProxy安装目录下的。所以，我把驱动版本从5.1.47改成8.0.13（Demo用的是同一个版本），问题依旧。另外，我还可以想到：最新版本的ShardingProxy是不是引入了bug？然后，我安装了它之前的4.1.0版本，重新测试了一遍，还是有问题。这个时候真的觉得没有别的可疑点了，能想到的点都检查过了。回到Demo程序本身，它和ShardingProxy的唯一联系就是DataSource的url。jdbc:mysql://127.0.0.1:3307/sharding_db?useServerPrepStmts=true&cachePrepStmts=true&serverTimezone=UTC库名和端口号配置正确，唯一可疑的是另外三个参数：useServerPrepStmtscachePrepStmtsserverTimezone其中，前两个参数和预编译SQL相关，是一个组合。所以我把url中的这两个参数去掉，测试了一下。这时，奇迹发生了，返回了正确的数据。至此，问题已经基本定位，但是根源是什么？是ShardingProxy的bug吗？第四步：Wireshark抓包分析MySQL协议。找到这个问题的解决方法后，同步给各位读者。同时，他还在ShardingProxy的GitHub上提交了issue，反馈最新进展。由于工作原因，暂时搁置这个问题，打算抽空继续研究。大约一周后，我想起了这个问题，然后开了一个issue了解调查的进展。很奇怪官方开发者复现这个问题后，主观上以为是应用的问题，然后就莫名其妙的关闭了这个issue。他们的回答是这样的：意思是：我们对预编译的SQL功能做了很多测试，这个没有问题。建议您更换应用的数据库连接池，抓包继续分析。（这说法真是让人很无语，根本不是程序员的严谨思维！）第二天开始用Wireshark抓包分析MySQL协议，想搞清楚到底是什么原因？同时联系了官方，让他们重开issue。Wireshark如何抓取MySQL协议的数据包这里就不展开了，大家可以上网查资料。注意Wireshark的过滤条件设置为：mysql||tcp.port==3307其中：mysql表示ShardingProxy与MySQLServer之间的数据包，tcp.port==3307表示Demo程序与ShardingProxy之间的数据包.启动Wireshark抓包后，再次使用Postman发起请求触发整个过程，即可成功抓包如下图所示。只需注意背景颜色为深蓝色的8个数据包即可。在本文第2章的原理部分，我已经详细介绍了ShardingProxy的预编译功能以及该过程的MySQL协议消息。这里的8个数据包和原理介绍完全一致。那么如何进一步分析呢？结合ShardingProxy的架构图来思考：Proxy只是应用程序和MySQLServer之间的一个中间代理。它完全实现了MySQL协议对MySQL命令进行解码和编码，然后加入了自己的分库分表逻辑。如果ShardingProxy内部有bug，那肯定是数据包的问题。顺着这个思路，我们很快就可以发现，MySQLServer在执行完ExecuteStatement后，向Proxy返回了正确的数据包，而Proxy却没有向应用程序返回正确的数据包。下图是倒数第二个Response包，由MySQLServer返回给Proxy，在Payload中可以看到那条记录的数据：下图是最后一个Response包，由Proxy返回给应用程序。Payload中只能看到表字段的定义，那条记录已经消失了。通过这一步的分析，已经确认：ShardingProxy存在BUG。然后，我把这些证据发给了官方开发者，对方开始关注，正式进入源码分析阶段。根因定位当天晚上，官方开发者定位根因并发出PullRequest。看了代码改动，只改了一行代码。ShardingProxy重新组装数据包返回给应用程序时，会抛出更改的代码行。由于我们的数据表中有一个date类型的字段，修改后的代码行强制将date类型转换为Timestamp类型，所以抛出异常。还有几个疑惑，我会根据我对源码的理解一一解答。①为什么代码抛出异常，ShardingProxy的控制台却不打印？上面的截图是：抛出ClassCastException的方法的整个调用链。由于ShardingProxy没有捕获到这个RuntimeException并打印日志，所以这个异常最后被netty吞掉了。②为什么ShardingProxy需要进行date到Timestamp的类型转换？从ShardingProxy的结构可以理解，因为Proxy只能在MySQL协议编解码后，在中间插入它的分库分表逻辑。对于date类型的字段，ShardingProxy通过JDBCAPI获取的查询结果仍然是Date类型。之所以需要转为Timestamp，是跟MySQL协议有关。下面是MySQL官方文档的描述：简单理解就是：在实现代码的时候，ShardingProxy使用一个范围最大的时间戳来存储三个可能的值date、datetime和timestamp，然后根据以上协议规范。③这个bug是不是只有使用SQL预编译功能才会触发？是的，只有在处理ExecuteStatement命令时才会调用此方法。为什么不能用于普通的SQL查询场景呢？这与MySQL协议有关。在普通的SQL查询场景中，payload不是二进制协议，而是普通的文本协议。这种情况下就不需要调用这个类进行转换了。至此，整个分析过程结束。本文写在最后，详细回顾了该bug的分析过程，总结了原理知识和排查经验。对于ShardingSphere这样的顶级开源项目，我个人认为也值得做一个深入的回顾。我不同意他们处理问题的方式。此外，在核心功能的自动化测试中肯定存在不完善的案例。否则，不可能在连续的多个版本中发现这个严重的bug。作者：罗君武简介：前亚马逊工程师，现58转转技术总监，持续分享个人成长经验，希望能为你的职业发展带来一些新思路。编辑：陶佳龙来源：转载自公众号IT人职场进阶（ID：BestITer）
