解Bug之路-中間件

前言

咱們的分庫分表中間件在線上運行了兩年多，到目前爲止還算穩定。在筆者將精力放在處理各類災難性事件(例如中間件物理機宕機/數據庫宕機/網絡隔離等突發事件)時。居然發現還有一些奇怪的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!

2020-03-1311:21:01:040[NIOREACTOR-20RW]frontIP=>ip1;sqlID=>12345678;rows=>1;sql=>update test_2 set value =1 where id=1 and status = 1;update test_2 set value =1 where id=2 and status = 1;

如上圖所示，(update1;update2)中update1的okay返回被驅動認爲是全部的返回。而後應用當即發送了update3。前腳剛發送,update2的okay返回就回來了而其恰好是0，應用就報錯了(要不是0，這個錯亂邏輯還不會提早暴露)。那三條"重複執行"也很好解釋了，就是以前的拼接sql會有三條。

爲什麼是機率出現

但奇怪的是，並非每次拼接sql都會形成update3"重複執行"的現象，按照筆者的推斷應該前面只要是多條拼接sql就會必現纔對。因而筆者翻了下jdbc驅動源碼，發現其在發送命令以前會清理下接收buffer，以下所示:

MysqlIO.javafinal Buffer sendCommand(......){
	......	// 清理接收buffer,會將殘存的okay包清除掉
	clearInputStream();
	......
	send(this.sendPacket, this.sendPacket.getPosition());
	......
}

正是因爲clearInputStream()使得錯誤非必現(暴露)，若是okay(update2)在應用發送第三條sql前先到jdbc驅動會被驅動忽略！
讓咱們再看一下不會讓update3"重複執行"的時序圖:

即根據okay(update2)返回的快慢來決定是否暴露這個問題,以下圖所示:

同時筆者觀察日誌，確實這種狀況下"update1;update2"這條語句在中間件裏面日誌有兩條。

臨時解決方案

讓業務開發不用這些拼接sql的寫法後，再也沒出過問題。

爲何不連中間件是okay的

業務開發這些sql是就在線上運行了很久，用了中間件後纔出現問題。
既然不連中間件是okay的，那麼jdbc必然有這方面的完善處理，筆者去翻了下mysql-connect-java(5.1.46)。因爲jdbc裏面存在大量的兼容細節處理，筆者這邊只列出一些關鍵代碼路徑:

MySQL JDBC 源碼
MySQLIO
stack;
executeUpdate
	|->executeUpdateInternel
		|->executeInternal
			|->execSQL
				|->sqlQueryDirect
					|->readAllResults (MysqlIO.java)
readAllResults: //核心在這個函數的處理裏面ResultSetImpl readAllResults(......){
		......       while (moreRowSetsExist) {
			  ......			  // 在返回okay包的保中其serverStatus字段中若是SERVER_MORE_RESULTS_EXISTS置位
			  // 代表還有更多的okay packet
            moreRowSetsExist = (this.serverStatus & SERVER_MORE_RESULTS_EXISTS) != 0;
        }
        ......
}

正確的處理流程以下圖所示:

而咱們中間件的源碼確實這麼處理的:

@Overridepublic void okResponse(byte[] data, BackendConnection conn) {
	......	// 這邊僅僅處理了autocommit的狀態，沒有處理SERVER_MORE_RESULTS_EXISTS
	// 因此致使了不兼容拼接sql的現象
	ok.serverStatus = source.isAutocommit() ? 2 : 1;
	ok.write(source);
	......
}

select也"重複執行"了

解決完上面的問題後，筆者在日誌里居然發現select盡然也有重複的，這邊並不會牽涉到okay包的處理，難道還有問題？日誌以下所示:

2020-03-13 12:21:01:040[NIOREACTOR-20RW]frontIP=>ip1;sqlID=>12345678;rows=>1;select abc;2020-03-13 12:21:01:045[NIOREACTOR-21RW]frontIP=>ip2;sqlID=>12345678;rows=>1;select abc;

從不一樣的REACTOR線程號(20RW/21RW)和不一樣的frontIP(ip1,ip2)來看是兩個鏈接執行了一樣的sql,但爲什麼sqlID是同樣的？任何一個詭異的現象都必須一查到底。因而筆者登陸到應用上看了下應用日誌，確實應用有兩個不一樣的線程運行了同一條sql。
那確定是中間件日誌打印的問題了,筆者很快就想通了其中的關竅，咱們中間件有個對一樣sql緩存其路由節點結構體的功能(這樣下一次一樣sql就沒必要解析，下降了CPU)，而sqlID信息正好也在那個路由節點結構體裏面。以下圖所示:

這個緩存功能感受沒啥用(由於線上基本是沒有相同sql的)，因而筆者在筆者優化的閃電模式下(大幅度提升中間件性能)將這個功能禁用掉了，沒想到爲了排查問題而開啓的詳細日誌碰巧將這個功能開啓了。

總結

任何系統都不能說百分之百穩定可靠，尤爲是不能立flag。在線上運行了好幾年的系統也是如此。只有對全部預料外的現象進行細緻的追查與深刻的分析並解決，才能讓咱們的系統愈來愈可靠。