[[356276]] 

圖片來自 Pexels

說實話，這是一次比較曲折的 Bug 跟蹤之旅。10 月 28 日，我們在 GitHub 上提交 issue，中途因為官方開發者的主觀臆斷被 Close 了兩次，直到 11 月 20 日才被認定成 Bug 并發出修復版本，歷時 20 多天。

本文將還原該 Bug 的分析過程，將有價值的經驗和技術點進行提煉。通過本文，你將收獲到：

• 疑難問題的排查思路
• 數據庫中間件 Sharding Proxy 的原理
• MySQL 預編譯的流程和交互協議
• Wireshark 抓包分析 MySQL 的奇淫技巧

問題描述

這個 Bug 來源于我的讀者，他替公司預研 ShardingProxy(屬于 ShardingSphere 的子產品，可用作分庫分表，后文會詳細介紹)。

他按照官方文檔寫了一個很簡單的 demo，但是運行后無法查詢出數據。

下面是他遇到問題后發給我的信息，希望我能幫忙一起定位下原因：

 

截圖中的 doc 詳細記錄了 ShardingProxy 的配置、調試分析日志、以及問題的具體現象。

為了方便大家理解，我重新描述下這個 Demo 的業務邏輯以及問題表象。

Demo 的業務邏輯說明

這個 Demo 很簡單，主要為了跑通 ShardingProxy 的分庫分表功能。程序用 SpringBoot+MyBatis 實現了一個單表的查詢邏輯，然后用這張表的一個 long 類型字段作為分區鍵，并通過 ShardingProxy 進行了分表。

下面是那張數據表的詳細定義，共 16 個字段，大家關注前兩個字段即可，其他字段和本文提到的 Bug 無關。

 

前兩個字段的作用如下：

• BIZ_DT：業務字段，date 類型，和 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 連接的是 ShardingProxy 的邏輯數據源 sharding_db，端口使用的是 3307，并非真正的底層數據庫以及 MySQL Server 的真實端口 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 3 款獨立的產品組成。本文重點普及下 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 到執行完畢。

一般分為以下 3 步：

• 詞法和語義解析
• 優化 SQL，制定執行計劃
• 執行并返回結果

但是很多情況下，一條 SQL 語句可能會反復執行，只是執行時的參數值不同。

而預編譯功能將這些值用占位符代替，最終達到一次編譯、多次運行的效果，省去了解析優化等過程，能大大提高 SQL 的執行效率。

假設我們要執行下面這條 SQL 兩次：

SELECT * FROM t_user WHERE user_id = 10;

那 JDBC 和 MySQL 之間的協議消息如下：

通過上述流程可以看到：

• 第 1 條消息是PreparedStatement，查詢語句中的參數值用問號代替了，它告訴 MySQL 對這個SQL 進行預編譯。
• 第 2 條消息 MySQL 告訴 JDBC 準備成功了。
• 第 3 條消息 JDBC 將參數設置為 1。
• 第 4 條消息 MySQL 返回查詢結果。
• 第 5 條和第 6 條消息表示第二次執行同樣的 SQL，已經無需再次預編譯了。

再回到 ShardingProxy，如果需要支持預編譯功能，交互流程肯定是需要變的，因為 Proxy 在收到 JDBC 的PreparedStatement 命令時，SQL 里的分片鍵是問號，它根本不知道該路由到哪個真實數據庫。

因此，流程變成了下面這樣：

 

可以看到，Proxy在收到 PreparedStatement 命令后，并不會把這條消息轉發給MySQL，只是緩存了這個 SQL，在收到 ExecuteStatement 命令后，才根據分片鍵和傳過來的參數值確定真實的數據庫，并與 MySQL 交互。

問題分析

上一章節基本把這個 Bug 相關的原理知識介紹清楚了，下面正式進入問題的分析過程。

最開始拿到這個問題，我也是比較頭禿的，尤其看到讀者下面這段信息。

當然，我的功力是達不到盲猜水平的，說下我的完整思路。

第 1 步：復現問題

我讓讀者給我打包發了 Demo 的源代碼、數據庫腳本以及 ShardingProxy 配置，然后本地安裝了 ShardingProxy 4.1.1 版本，再通過 Navicat 連接到 ShardingProxy 執行數據庫腳本，環境基本就準備完畢了。

啟動 Demo 程序后，通過 Postman 發送請求，問題穩定復現了，確實查不出數據。

第 2 步：確認應用程序是否有 Bug

因為整個代碼很簡單，代碼層面唯一有可能存在問題的是 Mybatis 這一層。

為了確認這一點，我修改了 SpringBoot 的配置，將 MyBatis 的 debug 日志也打印了出來。

再次發起請求后，能從控制臺中看到以下詳細日志：

 

日志中沒發現異常，而且 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 配置改回成原樣，繼續排查。

第 3 步：排查 ShardingProxy

首先，查看 ShardingProxy 的運行日志，沒發現任何異常;其次，能看到日志中的 Actual SQL 是正確的，它已經根據分區鍵正確路由到了 pcsct_prdt_cvr0 這張表：

[INFO ] 17:25:48.804 [ShardingSphere-Command-15]  
ShardingSphere-SQL - Actual SQL: ds_0 ::: SELECT  
BIZ_DT,ECIF_CUST_NO,DEP_FLG ...  
FROM pscst_prdt_cvr0  
WHERE ECIF_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 

庫名和端口號配置無誤，唯一可疑的是另外三個參數:

• useServerPrepStmts
• cachePrepStmts
• serverTimezone

其中，前兩個參數和預編譯 SQL 有關，是一個組合。因此，我將這兩個參數從 url 中去掉，測試了一下。

這個時候奇跡出現了，居然返回了正確數據。至此，基本定位到了問題，但根本原因是什么呢?究竟是不是 ShardingProxy 的 Bug ?

第 4 步：Wireshark 抓包分析 MySQL 協議

找到這個問題的解決方案后，我同步給了讀者。與此同時，他也在 ShardingProxy 的 GitHub 上提交了 issue，反饋了這個最新進展。

由于工作原因，這個問題我就暫時放一邊了，準備抽空再接著排查。

大概過了一周我想起了這個問題，然后打開 issue 想了解下調查進度，讓我非常驚訝的是：官方開發者居然在復現此問題后，主觀臆斷地認為是應用程序的問題，然后莫名奇妙的把這個 issue 關閉了。

他們的答復是這樣的：

 

意思就是：我們針對預編譯 SQL 功能做了大量的測試，這個是不可能存在問題的，建議你們更換下應用程序的數據庫連接池，抓包繼續分析下。(這個說法真讓人非常無語，完全不是程序員嚴謹的思維!)

第二天，我開始用 Wireshark 抓包分析 MySQL 的協議，想弄清楚根本原因到底是什么?同時聯系上了官方，讓他們 reopen 了這個問題。

Wireshark 如何抓取 MySQL 協議的數據包，這里就不展開了，大家可以網上查下資料。

注意將 Wireshark 的過濾條件設置成：

mysql || tcp.port==3307 

其中：mysql 表示 ShardingProxy 和 MySQL Server 之間的數據包，tcp.port==3307 表示 Demo 程序和 ShardingProxy 之間的數據包。

啟動 Wireshark 抓包后，再次用 Postman 發起請求，觸發整個過程，然后就能順利抓到下面截圖的數據包了。

 

大家關注底色為 深藍色 的 8 個數據包即可。在本文第 2 章節的原理部分，我已經詳細介紹過 ShardingProxy 的預編譯功能以及該流程的 MySQL 協議消息，這里的 8 個數據包和原理介紹是完成吻合的。

那接下來如何進一步分析呢?結合 ShardingProxy 的架構圖來思考下：Proxy 僅僅作為一個中間代理，介于應用程序和 MySQL Server 之間。

它完全實現了 MySQL 協議，以便對 MySQL 命令進行解碼和編碼，然后加上自己的分庫分表邏輯。

如果 ShardingProxy 內部存在 Bug，那一定是某個數據包出現了問題。

順著這個思路，很快就能發現：執行完 ExecuteStatement 后，MySQL Server 返回正確數據包給 Proxy 了，但是 Proxy 沒有返回正確的數據包給應用程序。

下面截圖的是倒數第 2 個 Response 數據包，由 MySQL Server 返回給 Proxy 的，Payload 中能看到那條記錄的數據：

下面截圖的是最后 1 個 Response 數據包，由 Proxy 返回給應用程序的，Payload 中只能看到表字段的定義，那條記錄已經不翼而飛了。

 

通過這一步分析，就已經坐實了：ShardingProxy 是有 Bug 的。然后，我將這些依據發給了官方開發者，對方開始重視，并正式進入源碼分析階段。

根本原因定位

當天晚上，官方開發者就定位到了根本原因，發出了 Pull Request。我看了下代碼改動，僅僅修改了一行代碼。

 

改動的這行代碼，就是在 ShardingProxy 再次組裝數據包返回給應用程序時拋出來的。

由于我們的數據表中存在一個 date 類型的字段，改動的這行代碼卻強制將 date 類型轉換成了 Timestamp 類型，因此拋出了異常。還有幾個疑點，我結合對源代碼的理解逐一解答下。

①為什么代碼拋異常了，但是 ShardingProxy 的控制臺沒打印呢?

 

上面截圖的是：拋出 ClassCastException 那個方法的整個調用鏈。由于 ShardingProxy 并沒有捕獲這個 RuntimeException 以及打印日志，最終這個異常被 netty 吞掉了。

②為什么 ShardingProxy 需要做 date 到 Timestamp 的類型轉換呢?

可以從 ShardingProxy 的架構來理解，因為 Proxy 只有對 MySQL 協議進行編解碼后，才能在中間插入它的分庫分表邏輯。

針對 date 類型的字段，ShardingProxy 通過 JDBC 的 API 從查詢結果中拿到的仍然是 Date 類型，之所以要轉換成 Timestamp，這個又跟 MySQL 的協議有關了，下面是 MySQL 官方文檔的說明：

 

簡單理解就是：ShardingProxy 在代碼實現時，用了一個范圍最大的 timestamp 存了三種可能的值 date，datetime 和 timestamp，然后再按照上面這個協議規范進行二進制的寫入。

③這個 Bug 是只有在使用 SQL 預編譯功能時才會被觸發嗎?

是的，只有在處理 ExecuteStatement 命令時，這個方法才會被調用到。那普通的 SQL 查詢場景為什么用不到呢?

這個又跟 MySQL 協議有關了，普通的 SQL 查詢場景，payload 不是二進制協議的，而是普通的文本協議。這種情況下，無需調用這個類進行轉換。

至此，整個分析過程就結束了。

寫在最后

本文詳細復盤了這個 Bug 的分析過程，并對其中的原理知識和排查經驗進行了總結。

對于 ShardingSphere 這種頂級開源項目來說，我個人覺得同樣值得做一次深度復盤。

我不認同他們對于 issue 的處理方式，另外在核心功能的自動化測試上，也一定是存在 case 不完善的，不然不可能連續多個版本都沒發現這個嚴重 Bug。

作者：駱俊武

簡介：前亞馬遜工程師，現 58 轉轉技術總監，持續分享個人的成長經歷，希望為你的職場發展帶來些新思路。

編輯：陶家龍

出處：轉載自公眾號IT人的職場進階(ID：BestITer)