給Apache頂級(jí)項(xiàng)目提Bug,我有點(diǎn)飄...
圖片來自 Pexels
說實(shí)話,這是一次比較曲折的 Bug 跟蹤之旅。10 月 28 日,我們在 GitHub 上提交 issue,中途因?yàn)楣俜介_發(fā)者的主觀臆斷被 Close 了兩次,直到 11 月 20 日才被認(rèn)定成 Bug 并發(fā)出修復(fù)版本,歷時(shí) 20 多天。
本文將還原該 Bug 的分析過程,將有價(jià)值的經(jīng)驗(yàn)和技術(shù)點(diǎn)進(jìn)行提煉。通過本文,你將收獲到:
- 疑難問題的排查思路
- 數(shù)據(jù)庫中間件 Sharding Proxy 的原理
- MySQL 預(yù)編譯的流程和交互協(xié)議
- Wireshark 抓包分析 MySQL 的奇淫技巧
問題描述
這個(gè) Bug 來源于我的讀者,他替公司預(yù)研 ShardingProxy(屬于 ShardingSphere 的子產(chǎn)品,可用作分庫分表,后文會(huì)詳細(xì)介紹)。
他按照官方文檔寫了一個(gè)很簡單的 demo,但是運(yùn)行后無法查詢出數(shù)據(jù)。
下面是他遇到問題后發(fā)給我的信息,希望我能幫忙一起定位下原因:
截圖中的 doc 詳細(xì)記錄了 ShardingProxy 的配置、調(diào)試分析日志、以及問題的具體現(xiàn)象。
為了方便大家理解,我重新描述下這個(gè) Demo 的業(yè)務(wù)邏輯以及問題表象。
Demo 的業(yè)務(wù)邏輯說明
這個(gè) Demo 很簡單,主要為了跑通 ShardingProxy 的分庫分表功能。程序用 SpringBoot+MyBatis 實(shí)現(xiàn)了一個(gè)單表的查詢邏輯,然后用這張表的一個(gè) long 類型字段作為分區(qū)鍵,并通過 ShardingProxy 進(jìn)行了分表。
下面是那張數(shù)據(jù)表的詳細(xì)定義,共 16 個(gè)字段,大家關(guān)注前兩個(gè)字段即可,其他字段和本文提到的 Bug 無關(guān)。
前兩個(gè)字段的作用如下:
- BIZ_DT:業(yè)務(wù)字段,date 類型,和 Bug 有關(guān)
- ECIF_CUST_NO:bigint 類型,用做分區(qū)鍵
代碼就是 Controller 調(diào)用 Service,Service 調(diào)用 Dao,Dao 通過 MyBatis 實(shí)現(xiàn),這里就不粘貼了。
由于使用了 ShardingProxy 中間件,因此它跟直連數(shù)據(jù)庫的配置會(huì)有所不同,在定義 dataSource 時(shí),url 需要配置成這樣:
jdbc:mysql://127.0.0.1:3307/sharding_db?useServerPrepStmts=true&cachePrepStmts=true&serverTimezone=UTC
可以看到,jdbc 連接的是 ShardingProxy 的邏輯數(shù)據(jù)源 sharding_db,端口使用的是 3307,并非真正的底層數(shù)據(jù)庫以及 MySQL Server 的真實(shí)端口 3306,具體原理下文會(huì)介紹到。
其中,標(biāo)藍(lán)色的 useServerPrepStmts 和 cachePrepStmts 這兩個(gè)參數(shù),和本文說的 Bug 有關(guān),這里先提一下,后面會(huì)具體分析。
另外,ShardingProxy 的分表策略是:用 long 類型的 ecif_cust_no 字段對 2 進(jìn)行取模,分成了兩張表。
具體配置如下:
shardingColumn: ecif_cust_noalgorithmExpression: pscst_prdt_cvr${ecif_cust_no % 2}
問題描述
再說下遇到的問題。首先,往數(shù)據(jù)表中預(yù)先插入一條 ECIF_CUST_NO 等于 10000 的數(shù)據(jù):
然后啟動(dòng) demo 程序,使用 curl 發(fā)起 post 請求,查詢 ecifCustNo 等于 10000 的那條記錄,居然查詢不出數(shù)據(jù):
至此,背景基本交代清楚了,為什么數(shù)據(jù)庫中明明有數(shù)據(jù),但是程序卻查詢不出來呢?問題到底出現(xiàn)在 ShardingProxy,還是應(yīng)用程序本身?
ShardingProxy 原理簡介
在開啟這個(gè)問題的分析過程之前,我先快速普及下 ShardingProxy 的基本原理,以便大家能更好的理解我的分析思路。
開源的數(shù)據(jù)庫中間件大家一定接觸過,最流行的是 MyCat 和 ShardingSphere。
其中 MyCat 是阿里開源的;ShardingSphere 是由當(dāng)當(dāng)網(wǎng)開源,并在京東逐漸發(fā)展壯大,于 2020 年成為了 Apache 頂級(jí)項(xiàng)目。
ShardingSphere 的目標(biāo)是一個(gè)生態(tài)圈,它由非常著名的 ShardingJDBC、ShardingProxy、ShardingSidecar 3 款獨(dú)立的產(chǎn)品組成。本文重點(diǎn)普及下 ShardingProxy,另外兩個(gè)就不展開了。
什么是 ShardingProxy?
ShardingProxy 屬于和 MyCat 對標(biāo)的產(chǎn)品,定位為透明化的數(shù)據(jù)庫代理端,可以理解成:一個(gè)實(shí)現(xiàn)了 MySQL 協(xié)議的 Server(獨(dú)立進(jìn)程),可用于讀寫分離、分庫分表、柔性事務(wù)等場景。
對于應(yīng)用程序或者 DBA 來說,可以把 ShardingProxy 當(dāng)做數(shù)據(jù)庫代理,能用 MySQL 客戶端工具(Navicat)或者命令行和它直接交互。
而 ShardingProxy 內(nèi)部則通過 MySQL 原生協(xié)議與真實(shí)的 MySQL 服務(wù)器通信。
圖 1:ShardingProxy 的應(yīng)用架構(gòu)圖
從架構(gòu)圖來看,ShardingProxy 就相當(dāng)于 MySQL,它本身不存儲(chǔ)數(shù)據(jù),但是對外屏蔽了 Database 的存儲(chǔ)細(xì)節(jié)。
你可以用連接 MySQL 的方式去連接 ShardingProxy(除了端口不同),用你熟悉的 ORMapping 框架使用它。
ShardingProxy 的內(nèi)部架構(gòu)
再來看下 ShardingProxy 的內(nèi)部架構(gòu),后續(xù)源碼分析時(shí)會(huì)涉及到此部分。
圖 2:ShardingProxy 的內(nèi)部架構(gòu)圖
整個(gè)架構(gòu)分為前端、核心組件和后端:
- 前端(Frontend):負(fù)責(zé)與客戶端進(jìn)行網(wǎng)絡(luò)通信,采用的是 NIO 框架,在通信的過程中完成對MySQL協(xié)議的編解碼。
- 核心組件(Core-module):得到解碼的 MySQL 命令后,開始調(diào)用 Sharding-Core 對 SQL 進(jìn)行解析、改寫、路由、歸并等核心功能。
- 后端(Backend):與真實(shí)數(shù)據(jù)庫交互,采用 Hikari 連接池,同樣涉及到 MySQL 協(xié)議的編解碼。
ShardingProxy 的預(yù)編譯 SQL 功能
本文的 Bug 跟 ShardingProxy 的預(yù)編譯 SQL 有關(guān),這里單獨(dú)介紹下此功能以及與之相關(guān)的 MySQL 協(xié)議,這個(gè)是本文的關(guān)鍵,請耐心看完。
熟悉數(shù)據(jù)庫開發(fā)的同學(xué)一定了解:預(yù)編譯 SQL(PreparedStatement),在數(shù)據(jù)庫收到一條 SQL 到執(zhí)行完畢。
一般分為以下 3 步:
- 詞法和語義解析
- 優(yōu)化 SQL,制定執(zhí)行計(jì)劃
- 執(zhí)行并返回結(jié)果
但是很多情況下,一條 SQL 語句可能會(huì)反復(fù)執(zhí)行,只是執(zhí)行時(shí)的參數(shù)值不同。
而預(yù)編譯功能將這些值用占位符代替,最終達(dá)到一次編譯、多次運(yùn)行的效果,省去了解析優(yōu)化等過程,能大大提高 SQL 的執(zhí)行效率。
假設(shè)我們要執(zhí)行下面這條 SQL 兩次:
SELECT * FROM t_user WHERE user_id = 10;
那 JDBC 和 MySQL 之間的協(xié)議消息如下:
通過上述流程可以看到:
- 第 1 條消息是PreparedStatement,查詢語句中的參數(shù)值用問號(hào)代替了,它告訴 MySQL 對這個(gè)SQL 進(jìn)行預(yù)編譯。
- 第 2 條消息 MySQL 告訴 JDBC 準(zhǔn)備成功了。
- 第 3 條消息 JDBC 將參數(shù)設(shè)置為 1。
- 第 4 條消息 MySQL 返回查詢結(jié)果。
- 第 5 條和第 6 條消息表示第二次執(zhí)行同樣的 SQL,已經(jīng)無需再次預(yù)編譯了。
再回到 ShardingProxy,如果需要支持預(yù)編譯功能,交互流程肯定是需要變的,因?yàn)?Proxy 在收到 JDBC 的PreparedStatement 命令時(shí),SQL 里的分片鍵是問號(hào),它根本不知道該路由到哪個(gè)真實(shí)數(shù)據(jù)庫。
因此,流程變成了下面這樣:
可以看到,Proxy在收到 PreparedStatement 命令后,并不會(huì)把這條消息轉(zhuǎn)發(fā)給MySQL,只是緩存了這個(gè) SQL,在收到 ExecuteStatement 命令后,才根據(jù)分片鍵和傳過來的參數(shù)值確定真實(shí)的數(shù)據(jù)庫,并與 MySQL 交互。
問題分析
上一章節(jié)基本把這個(gè) Bug 相關(guān)的原理知識(shí)介紹清楚了,下面正式進(jìn)入問題的分析過程。
最開始拿到這個(gè)問題,我也是比較頭禿的,尤其看到讀者下面這段信息。
當(dāng)然,我的功力是達(dá)不到盲猜水平的,說下我的完整思路。
第 1 步:復(fù)現(xiàn)問題
我讓讀者給我打包發(fā)了 Demo 的源代碼、數(shù)據(jù)庫腳本以及 ShardingProxy 配置,然后本地安裝了 ShardingProxy 4.1.1 版本,再通過 Navicat 連接到 ShardingProxy 執(zhí)行數(shù)據(jù)庫腳本,環(huán)境基本就準(zhǔn)備完畢了。
啟動(dòng) Demo 程序后,通過 Postman 發(fā)送請求,問題穩(wěn)定復(fù)現(xiàn)了,確實(shí)查不出數(shù)據(jù)。
第 2 步:確認(rèn)應(yīng)用程序是否有 Bug
因?yàn)檎麄€(gè)代碼很簡單,代碼層面唯一有可能存在問題的是 Mybatis 這一層。
為了確認(rèn)這一點(diǎn),我修改了 SpringBoot 的配置,將 MyBatis 的 debug 日志也打印了出來。
再次發(fā)起請求后,能從控制臺(tái)中看到以下詳細(xì)日志:
日志中沒發(fā)現(xiàn)異常,而且 PreparedStatement 以及 ExecuteStatement 的參數(shù)設(shè)置都是正確的,查詢結(jié)果確實(shí)是空。
為了縮小排查范圍,我把 dataSource 的 配置改回了直連真實(shí)數(shù)據(jù)庫,這樣能將 ShardingProxy 這個(gè)干擾因素排除在外。
改完后的 url 如下:
jdbc:mysql://127.0.0.1:3306/db1?useServerPrepStmts=true&cachePrepStmts=true&serverTimezone=UTC
其中,db1 是真實(shí)數(shù)據(jù)庫,3306 也是MySQL 服務(wù)器的端口了。然后再次用 Postman 發(fā)送請求,可以看到:有正確數(shù)據(jù)返回了。
通過這一步,我將懷疑對象再次轉(zhuǎn)移到 ShardingProxy 上了,并將 dataSource 配置改回成原樣,繼續(xù)排查。
第 3 步:排查 ShardingProxy
首先,查看 ShardingProxy 的運(yùn)行日志,沒發(fā)現(xiàn)任何異常;其次,能看到日志中的 Actual SQL 是正確的,它已經(jīng)根據(jù)分區(qū)鍵正確路由到了 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 的分庫分表配置應(yīng)該是沒有問題的。
我開始懷疑:是否跟 ShardingProxy 所使用的數(shù)據(jù)庫驅(qū)動(dòng)有關(guān)?因?yàn)檫@個(gè) Jar 包是應(yīng)用方選擇版本,手動(dòng)放到 ShardingProxy 安裝目錄中的。
因此,我將驅(qū)動(dòng)版本從 5.1.47 版本改成了 8.0.13 (和 Demo 使用了相同的版本),但是問題仍然存在。
另外,還能想到的是:是否是 ShardingProxy 的這個(gè)最新版本引入了 Bug?然后,我又另外安裝了它的上一個(gè)版本 4.1.0,重新測試了一遍,還是有問題。
這個(gè)時(shí)候,真感覺沒有其他可疑點(diǎn)了,所有能想到的點(diǎn)都排查了一遍。我再次回到了 Demo 程序本身,它和 ShardingProxy 唯一的結(jié)合點(diǎn)就在 DataSource 的 url 上。
- jdbc:mysql://127.0.0.1:3307/sharding_db?useServerPrepStmts=true&cachePrepStmts=true&serverTimezone=UTC
庫名和端口號(hào)配置無誤,唯一可疑的是另外三個(gè)參數(shù):
- useServerPrepStmts
- cachePrepStmts
- serverTimezone
其中,前兩個(gè)參數(shù)和預(yù)編譯 SQL 有關(guān),是一個(gè)組合。因此,我將這兩個(gè)參數(shù)從 url 中去掉,測試了一下。
這個(gè)時(shí)候奇跡出現(xiàn)了,居然返回了正確數(shù)據(jù)。至此,基本定位到了問題,但根本原因是什么呢?究竟是不是 ShardingProxy 的 Bug ?
第 4 步:Wireshark 抓包分析 MySQL 協(xié)議
找到這個(gè)問題的解決方案后,我同步給了讀者。與此同時(shí),他也在 ShardingProxy 的 GitHub 上提交了 issue,反饋了這個(gè)最新進(jìn)展。
由于工作原因,這個(gè)問題我就暫時(shí)放一邊了,準(zhǔn)備抽空再接著排查。
大概過了一周我想起了這個(gè)問題,然后打開 issue 想了解下調(diào)查進(jìn)度,讓我非常驚訝的是:官方開發(fā)者居然在復(fù)現(xiàn)此問題后,主觀臆斷地認(rèn)為是應(yīng)用程序的問題,然后莫名奇妙的把這個(gè) issue 關(guān)閉了。
他們的答復(fù)是這樣的:
意思就是:我們針對預(yù)編譯 SQL 功能做了大量的測試,這個(gè)是不可能存在問題的,建議你們更換下應(yīng)用程序的數(shù)據(jù)庫連接池,抓包繼續(xù)分析下。(這個(gè)說法真讓人非常無語,完全不是程序員嚴(yán)謹(jǐn)?shù)乃季S!)
第二天,我開始用 Wireshark 抓包分析 MySQL 的協(xié)議,想弄清楚根本原因到底是什么?同時(shí)聯(lián)系上了官方,讓他們 reopen 了這個(gè)問題。
Wireshark 如何抓取 MySQL 協(xié)議的數(shù)據(jù)包,這里就不展開了,大家可以網(wǎng)上查下資料。
注意將 Wireshark 的過濾條件設(shè)置成:
- mysql || tcp.port==3307
其中:mysql 表示 ShardingProxy 和 MySQL Server 之間的數(shù)據(jù)包,tcp.port==3307 表示 Demo 程序和 ShardingProxy 之間的數(shù)據(jù)包。
啟動(dòng) Wireshark 抓包后,再次用 Postman 發(fā)起請求,觸發(fā)整個(gè)過程,然后就能順利抓到下面截圖的數(shù)據(jù)包了。
大家關(guān)注底色為 深藍(lán)色 的 8 個(gè)數(shù)據(jù)包即可。在本文第 2 章節(jié)的原理部分,我已經(jīng)詳細(xì)介紹過 ShardingProxy 的預(yù)編譯功能以及該流程的 MySQL 協(xié)議消息,這里的 8 個(gè)數(shù)據(jù)包和原理介紹是完成吻合的。
那接下來如何進(jìn)一步分析呢?結(jié)合 ShardingProxy 的架構(gòu)圖來思考下:Proxy 僅僅作為一個(gè)中間代理,介于應(yīng)用程序和 MySQL Server 之間。
它完全實(shí)現(xiàn)了 MySQL 協(xié)議,以便對 MySQL 命令進(jìn)行解碼和編碼,然后加上自己的分庫分表邏輯。
如果 ShardingProxy 內(nèi)部存在 Bug,那一定是某個(gè)數(shù)據(jù)包出現(xiàn)了問題。
順著這個(gè)思路,很快就能發(fā)現(xiàn):執(zhí)行完 ExecuteStatement 后,MySQL Server 返回正確數(shù)據(jù)包給 Proxy 了,但是 Proxy 沒有返回正確的數(shù)據(jù)包給應(yīng)用程序。
下面截圖的是倒數(shù)第 2 個(gè) Response 數(shù)據(jù)包,由 MySQL Server 返回給 Proxy 的,Payload 中能看到那條記錄的數(shù)據(jù):
下面截圖的是最后 1 個(gè) Response 數(shù)據(jù)包,由 Proxy 返回給應(yīng)用程序的,Payload 中只能看到表字段的定義,那條記錄已經(jīng)不翼而飛了。
通過這一步分析,就已經(jīng)坐實(shí)了:ShardingProxy 是有 Bug 的。然后,我將這些依據(jù)發(fā)給了官方開發(fā)者,對方開始重視,并正式進(jìn)入源碼分析階段。
根本原因定位
當(dāng)天晚上,官方開發(fā)者就定位到了根本原因,發(fā)出了 Pull Request。我看了下代碼改動(dòng),僅僅修改了一行代碼。
改動(dòng)的這行代碼,就是在 ShardingProxy 再次組裝數(shù)據(jù)包返回給應(yīng)用程序時(shí)拋出來的。
由于我們的數(shù)據(jù)表中存在一個(gè) date 類型的字段,改動(dòng)的這行代碼卻強(qiáng)制將 date 類型轉(zhuǎn)換成了 Timestamp 類型,因此拋出了異常。還有幾個(gè)疑點(diǎn),我結(jié)合對源代碼的理解逐一解答下。
①為什么代碼拋異常了,但是 ShardingProxy 的控制臺(tái)沒打印呢?
上面截圖的是:拋出 ClassCastException 那個(gè)方法的整個(gè)調(diào)用鏈。由于 ShardingProxy 并沒有捕獲這個(gè) RuntimeException 以及打印日志,最終這個(gè)異常被 netty 吞掉了。
②為什么 ShardingProxy 需要做 date 到 Timestamp 的類型轉(zhuǎn)換呢?
可以從 ShardingProxy 的架構(gòu)來理解,因?yàn)?Proxy 只有對 MySQL 協(xié)議進(jìn)行編解碼后,才能在中間插入它的分庫分表邏輯。
針對 date 類型的字段,ShardingProxy 通過 JDBC 的 API 從查詢結(jié)果中拿到的仍然是 Date 類型,之所以要轉(zhuǎn)換成 Timestamp,這個(gè)又跟 MySQL 的協(xié)議有關(guān)了,下面是 MySQL 官方文檔的說明:
簡單理解就是:ShardingProxy 在代碼實(shí)現(xiàn)時(shí),用了一個(gè)范圍最大的 timestamp 存了三種可能的值 date,datetime 和 timestamp,然后再按照上面這個(gè)協(xié)議規(guī)范進(jìn)行二進(jìn)制的寫入。
③這個(gè) Bug 是只有在使用 SQL 預(yù)編譯功能時(shí)才會(huì)被觸發(fā)嗎?
是的,只有在處理 ExecuteStatement 命令時(shí),這個(gè)方法才會(huì)被調(diào)用到。那普通的 SQL 查詢場景為什么用不到呢?
這個(gè)又跟 MySQL 協(xié)議有關(guān)了,普通的 SQL 查詢場景,payload 不是二進(jìn)制協(xié)議的,而是普通的文本協(xié)議。這種情況下,無需調(diào)用這個(gè)類進(jìn)行轉(zhuǎn)換。
至此,整個(gè)分析過程就結(jié)束了。
寫在最后
本文詳細(xì)復(fù)盤了這個(gè) Bug 的分析過程,并對其中的原理知識(shí)和排查經(jīng)驗(yàn)進(jìn)行了總結(jié)。
對于 ShardingSphere 這種頂級(jí)開源項(xiàng)目來說,我個(gè)人覺得同樣值得做一次深度復(fù)盤。
我不認(rèn)同他們對于 issue 的處理方式,另外在核心功能的自動(dòng)化測試上,也一定是存在 case 不完善的,不然不可能連續(xù)多個(gè)版本都沒發(fā)現(xiàn)這個(gè)嚴(yán)重 Bug。
作者:駱俊武
簡介:前亞馬遜工程師,現(xiàn) 58 轉(zhuǎn)轉(zhuǎn)技術(shù)總監(jiān),持續(xù)分享個(gè)人的成長經(jīng)歷,希望為你的職場發(fā)展帶來些新思路。
編輯:陶家龍
出處:轉(zhuǎn)載自公眾號(hào)IT人的職場進(jìn)階(ID:BestITer)