# 解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狀態啊！ ## 應用大部分機器都連的是老庫! 這時候，開發向筆者反應，這個應用對應的大部分機器都是連的老庫！如果是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是沒有定時心跳檢測的。 ## 主從切換到底有沒有成功呢？ 主從切換當然是成功的。這從其它的應用切過去之後執行良好可以判斷出來。主從切換當中的資料庫流量損失是我們可預期的正常現象。但是，資料庫切換完之後，應用確恢復不回來，那就要仔細看看應用程式碼本身有什麼問題了。 ## 總結 資料庫主從切換是個頻繁而又重要的動作,是保證業務連續性的必要條件。這不僅要看DBA的努力，還需要我們在應用層寫出健壯的程式碼，才能夠讓我們的產線更加穩定。