解Bug之路-主從切換"未成功"?

前言

數據庫主從切換是個非常有意思的話題。能夠穩定的處理主從切換是保證業務連續性的必要條件。今天筆者就來講講主從切換過程中一個小小的問題。

故障場景

最近線上進行主從切換，大部分應用都切過去了，但是某些應用的連接確還在老的主(新的從)上面。

這讓對應應用的開發百思不得其解，于是求助了筆者一探究竟。

怎么發現的

應用開發收到Cat監控告警，發現這個應用(A)中的請求在好幾臺機器中一直穩定失敗。聯想到昨晚剛做過數據庫主從切換演練，于是上機器netstat -anp下，發現機器一直連的是舊的從庫！

netstat -anp | grep 1521
tcp 0 0 1.2.3.4:54100 1.1.1.1:1521 ESTABLISHED

開發感覺肯定是主從沒有切換過去導致請求失敗。乍一看，好像非常有道理的樣子。

著手調查

神馬情況？距離切換成功已經8個小時了，為什么連接還連在上面呢？于是筆者ping了下對應數據庫的域名:

ping db.prd
64byres from db.prd (2.2.2.2): icmp_seq=1 ttl=64 time=0.02ms

好奇怪，DNS已經切換過去了。應用怎么還連到老庫呢?

第一個猜想，DNS延遲

最先想到的是主從切換到DNS反應過來有延遲。例如主從切換完，DNS在2min后才能生效,所以在此期間新建的連接還是到從庫。

這種情況很正常，對于這種情況需要DBA將舊主的連接全都殺掉即可。咨詢了下DBA,他們反饋他們已經把連接全部殺掉了。而且當場給我看了下數據庫的統計連接SQL,確實沒有對應機器的連接。這就奇怪了，應用機器上的連接是ESTABLISHED狀態?。?/p>

應用大部分機器都連的是老庫!

這時候，開發向筆者反應，這個應用對應的大部分機器都是連的老庫！如果是DNS延遲，不可能這么巧吧，40多臺呢！

而且這些機器的DNS都是指向新庫的。

DB沒有kill連接?

難道是DBA漏了kill連接的步驟？但是和他和我展示的DB統計信息矛盾啊。于是筆者讓DBA在對應老庫的機器上netstat了一把。發現，連接還真的存在！

netstat -anp | grep 1.2.3.4
tcp 0 0 1.1.1.1:1521 1.2.3.4:54100 ESTABLISHED

難道統計信息真的有問題?

獲取連接創建時間

為了驗證筆者對于DNS延遲的猜想，就通過一些技巧來獲取這個連接的創建時間。首先
netstat -anp | grep 1.2.3.4找出來這個連接。由于明顯是屬于應用java進程的，所以
直接找到進程pid:8299

netstat -anp | grep 1521
tcp 0 0 1.2.3.4:54100 1.1.1.1:1521 ESTABLISHED

netstat -anp | grep java
abc 8299 java

既然有了進程pid,我們直接cat /proc/8299/net/tcp，直接獲取到其所有的連接信息,然后在其中grep 1521的16進制05F1(當前機器上1521的連接只有一個)

...... local_address rem_address inode     ......
...... xxx:D345      xxx:05F1    23456789  ......

找到這個socket(1.2.3.4:54100<->1.1.1.1:1521)對應的inode號。
有了這個inode號就簡單了，我們直接

ls -all -h /proc/8299/fd | grep 23456789 (inode號)
...... Jan 29 17:43 222 -> socket:[23456789]

這么一看，這個連接是1月29日創建的。但是主從切換的時間點確是3月19日,
這個連接已經建了2個月了！那么就不可能是筆者所說的DNS失效問題了。因為連接就沒有重連過。

DB都重啟了，怎么還有舊的連接保持?

看到這個連接創建時間，筆者第一反應，DBA確定殺連接了嗎？問了下DBA有沒有可能是統計問題。DBA聽了后，告訴筆者，他們都重啟過數據庫了，怎么可能還有連接存在呢？看了下DB進程的創建時間。

ps -eo lstart,cmd | grep db進程名
Mar 19 17:52:32 2021 db進程名

從進程啟動時間來看，真的是在3月19日啟動的。而這個詭異的連接還確實屬于這個3月19日啟動的進程。這個怎么看邏輯上都不通啊。

但是，既然linux的統計信息在這(還是要先暫時認為是靠譜的)，那肯定是又有什么其它的詭異邏輯在里面了。

子進程繼承了父進程的連接

稍微思考了一會，筆者就找到了一種可能。父進程先新建了連接進行處理，在創建子進程fork的時候，子進程會繼承父進程的連接，這時候父進程退出，只保留子進程的話。就會出現連接在進程啟動之前就已經存在的詭異現象。

為了驗證這個問題，筆者自己寫了段簡單的C程序，執行了一下確實如此。代碼例子為:

main.c
......
int main(int argc,char* argv[]){
	......
	if((client_fd = accept(sockfd,(struct sockaddr*)&remote_addr,&sin_size)) == -1){
		printf("accept error!\n");
	}
	printf("Received a connection \n");
	// 制造兩分鐘延遲，以造成上面的現象
	sleep(2 * 60);
	if(!fork()){
		// 子進程保持
		while(1){
		   sleep(100000);
		}
	}else{
		// 父進程關閉連接
		close(client_fd);
	}
	return 0;
}

問了下DBA，他們不會kill -9所有進程,都是按照標準的數據庫重啟流程來操作的(kill -9所有進程的同時會關閉這些進程所擁有的連接,但這么暴力的操作明顯不敢用在DB上)
如果我們使用的商業數據庫用了上圖的機制，那就會造成前面的現象。但是由于DB本身保持的session都已經沒了，那么這個連接在數據庫維度肯定是已經gg了(這也是數據庫統計不出來的原因)。既然還保留在上面，這個連接肯定再也沒有處理過請求！不然肯定出錯了。

業務代碼邏輯

如果按照上面的論斷的話，那么沒有執行過請求，也就不會有報錯嘍？如果按照這個邏輯的話，那豈不是只有出現業務報錯的才會有新的正常連接。筆者去報錯的機器看了下，既然報錯了，那肯定是執行過SQL了，然后觸發Druid丟棄連接再新建連接。
果然，一直報錯的機器上連接都連到新庫了(但應用開發發現其它機器還是連到老庫，所以找到了我求助)，而且創建時間是3月29日，而不報錯的應用的連接掛在老庫上面，挑了幾臺看一下，這些掛在老庫的連接依舊是1月29日創建的。

但為什么還在報錯?

既然連接都正常了(到新庫了)，為何還在報錯呢？難道說業務代碼寫的有問題，一旦報錯，就永遠錯下去？于是筆者直接翻起了應用的源碼。其使用這個數據庫的連接用來獲取(sequence)序列號。然后細細分析了源碼后發現。其在數據庫報錯之后沒有處理好，走了一個有問題的代碼分支，導致永遠不會再從數據庫獲取sequence(業務代碼就不放上來了)。

為什么只有幾臺機器報錯?

因為這個序列號是取一段很大的范圍到機器的內存中使用的，不耗盡之前不會執行SQL。所以只有一些內存中序列耗盡的機器才會運行到那一段有問題的代碼分支。

為什么心跳沒有檢測出來？

到這里大家可能會疑問？沒有心跳檢測么？確實沒有，應用采用的是Druid數據源，而他們使用的那個版本的Druid是沒有定時心跳檢測的。

主從切換到底有沒有成功呢？

主從切換當然是成功的。這從其它的應用切過去之后運行良好可以判斷出來。主從切換當中的數據庫流量損失是我們可預期的正?，F象。但是，數據庫切換完之后，應用確恢復不回來，那就要仔細看看應用代碼本身有什么問題了。

總結

數據庫主從切換是個頻繁而又重要的動作,是保證業務連續性的必要條件。這不僅要看DBA的努力，還需要我們在應用層寫出健壯的代碼，才能夠讓我們的產線更加穩定。