我給 Apache 頂級專案提了個 Bug

IT人的職場進階發表於2020-11-26

這篇文章記錄了給 Apache 頂級專案 - 分庫分表中介軟體 ShardingSphere 提交 Bug 的歷程。

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

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

1、疑難問題的排查思路

2、資料庫中介軟體 Sharding Proxy 的原理

3、MySQL 預編譯的流程和互動協議

4、Wireshark 抓包分析 MySQL 的奇淫技巧


01 問題描述

這個 Bug 來源於我的公號讀者,他替公司預研 ShardingProxy(屬於 ShardingSphere 的子產品,可用作分庫分表,後文會詳細介紹)。他按照官方文件寫了一個很簡單的 demo,但是執行後無法查詢出資料。

下面是他遇到問題後發給我的資訊,希望我能幫忙一起定位下原因。

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

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


1. 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_no

algorithmExpression: pscst_prdt_cvr${ecif_cust_no % 2}


2. 問題描述

再說下遇到的問題。首先,往資料表中預先插入一條 ECIF_CUST_NO 等於 10000 的資料:

然後啟動 demo 程式,使用 curl 發起 post 請求,查詢 ecifCustNo 等於 10000 的那條記錄,居然查詢不出資料:

至此,背景基本交代清楚了,為什麼資料庫中明明有資料,但是程式卻查詢不出來呢?問題到底出現在 ShardingProxy,還是應用程式本身?


02 ShardingProxy 原理簡介

在開啟這個問題的分析過程之前,我先快速普及下 ShardingProxy 的基本原理,以便大家能更好的理解我的分析思路。

開源的資料庫中介軟體大家一定接觸過,最流行的是 MyCat 和 ShardingSphere。其中 MyCat 是阿里開源的;ShardingSphere 是由噹噹網開源,並在京東逐漸發展壯大,於 2020 年成為了 Apache 頂級專案。

ShardingSphere 的目標是一個生態圈,它由非常著名的 ShardingJDBC、ShardingProxy、ShardingSidecar 3 款獨立的產品組成。本文重點普及下 ShardingProxy,另外兩個就不展開了。


1. 什麼是 ShardingProxy ?

ShardingProxy 屬於和 MyCat 對標的產品,定位為透明化的資料庫代理端,可以理解成:一個實現了 MySQL 協議的 Server(獨立程式),可用於讀寫分離、分庫分表、柔性事務等場景。

對於應用程式或者 DBA 來說,可以把 ShardingProxy 當做資料庫代理,能用 MySQL 客戶端工具(Navicat)或者命令列和它直接互動,而 ShardingProxy 內部則通過 MySQL 原生協議與真實的 MySQL 伺服器通訊。

從架構圖來看,ShardingProxy 就相當於 MySQL,它本身不儲存資料,但是對外遮蔽了 Database 的儲存細節,你可以用連線 MySQL 的方式去連線 ShardingProxy(除了埠不同),用你熟悉的 ORMapping 框架使用它。


2. ShardingProxy 的內部架構

再來看下 ShardingProxy 的內部架構,後續原始碼分析時會涉及到此部分。

整個架構分為前端、核心元件和後端:

前端(Frontend)負責與客戶端進行網路通訊,採用的是 NIO 框架,在通訊的過程中完成對MySQL協議的編解碼。

核心元件(Core-module)得到解碼的 MySQL 命令後,開始呼叫 Sharding-Core 對 SQL 進行解析、改寫、路由、歸併等核心功能。

後端(Backend)與真實資料庫互動,採用 Hikari 連線池,同樣涉及到 MySQL 協議的編解碼。


3. ShardingProxy 的預編譯 SQL 功能

本文的 Bug 跟 ShardingProxy 的預編譯 SQL 有關,這裡單獨介紹下此功能以及與之相關的 MySQL 協議,這個是本文的關鍵,請耐心看完。

熟悉資料庫開發的同學一定了解:預編譯 SQL(PreparedStatement),在資料庫收到一條 SQL 到執行完畢,一般分為以下 3 步:

1、詞法和語義解析

2、優化 SQL,制定執行計劃

3、執行並返回結果

但是很多情況下,一條 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 互動。


03 問題分析

上一章節基本把這個 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 的。然後,我將這些依據發給了官方開發者,對方開始重視,並正式進入原始碼分析階段。


04 根本原因定位

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

改動的這行程式碼,就是在 ShardingProxy 再次組裝資料包返回給應用程式時丟擲來的。

由於我們的資料表中存在一個 date 型別的欄位,改動的這行程式碼卻強制將 date 型別轉換成了 Timestamp 型別,因此丟擲了異常。還有幾個疑點,我結合對原始碼的理解逐一解答下。

1、為什麼程式碼拋異常了,但是 ShardingProxy 的控制檯沒列印呢?

上面截圖的是:丟擲 ClassCastException 那個方法的整個呼叫鏈。由於 ShardingProxy 並沒有捕獲這個 RuntimeException 以及列印日誌,最終這個異常被 netty 吞掉了。

2、為什麼 ShardingProxy 需要做 date 到 Timestamp 的型別轉換呢?

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

針對 date 型別的欄位,ShardingProxy 通過 JDBC 的 API 從查詢結果中拿到的仍然是 Date 型別,之所以要轉換成 Timestamp,這個又跟 MySQL 的協議有關了,下面是 MySQL 官方文件的說明:

簡單理解就是:ShardingProxy 在程式碼實現時,用了一個範圍最大的 timestamp 存了三種可能的值 date, datetime 和 timestamp,然後再按照上面這個協議規範進行二進位制的寫入。

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

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

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

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


05 寫在最後

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

對於 ShardingSphere 這種頂級開源專案來說,我個人覺得同樣值得做一次深度覆盤。我不認同他們對於 issue 的處理方式,另外在核心功能的自動化測試上,也一定是存在 case 不完善的,不然不可能連續多個版本都沒發現這個嚴重 Bug。

如果你有任何疑問,歡迎評論區留言討論。


作者簡介:985碩士,前亞馬遜工程師,現58轉轉技術總監

歡迎掃描下方的二維碼,關注我的個人公眾號:IT人的職場進階

相關文章