故障分析 | 手動 rm 掉 binlog 導致主從報錯

愛可生雲資料庫 發表於 2022-05-16

作者:陳偉

愛可生資料庫工程師,負責MySQL日常維護及故障處理。

本文來源:原創投稿

*愛可生開源社群出品,原創內容未經授權不得隨意使用,轉載請聯絡小編並註明來源。


1.故障描述

前一段時間客戶反饋複製報錯 1236 ,根據報錯提示該報錯為從庫讀取到了主庫不存在的 binlog 日誌,導致複製中斷,報錯截圖如下,需要幫忙分析為什麼會報錯 Could not open log file 原因。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

2.故障分析

說明:考慮客戶資訊敏感性,以下分析過程均在測試環境模擬,資料庫版本 5.7.31 ,GTID 啟用。

2.1.先登入從庫檢視報錯資訊

故障分析 | 手動 rm 掉 binlog 導致主從報錯

發現從庫的 io 執行緒斷了,並報錯:Got fatal error 1236 from master when reading data from binary log: 'Could not open log file' ,從字面意思不難理解,無法從主庫獲取到 binlog 日誌,GTID 停止在 828415 ,檢查從庫 error 日誌報錯如下:

故障分析 | 手動 rm 掉 binlog 導致主從報錯

根據從庫報錯資訊,下一步我們去主庫檢視主庫的 binlog 資訊和 error 日誌,看主庫 binlog 是否有丟失的情況。

2.2.檢視主庫 binlog 資訊,以及 error 日誌

登入主庫檢查 binlog 日誌列表以及 index 索引檔案,發現主庫的 binlog 是連續的沒有問題,但在檢視 mysql-bin.index 檔案的時候發現有記錄兩個 mysql-bin.000006 ,但是實際只有一個 mysql-bin.000006 檔案,先記著這個奇怪的現象。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

再去看一眼主庫的 error 日誌,內容如下,和從庫 error 日誌都指向同一個 binlog 。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

到這我們可以確認問題出在 mysql-bin.000006 這個 binlog 日誌上,但是從上面的圖中可以發現主庫的 binlog 日誌是有 mysql-bin.000006 這個日誌的,所以我們現在解析一下指向的 mysql-bin.000006 日誌以及前一個日誌 mysql-bin.000005 。

通過解析 mysql-bin.000005 可以看到最後一個事務 gtid 為:'c582a82e-b985-11ec-adf5-02000aba3e89:828415'為上面從庫停止 gtid 的位置。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

繼續解析 mysql-bin.000006 檢視其第一個事務的 gtid 為:'c582a82e-b985-11ec-adf5-02000aba3e89:855706' 。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

mysql-bin.000006 第一個 GTID 事務為 855706 ,與 binlog.000005 檔案相差了兩萬多個的 GTID 事務,與上一個 binlog.000005 並不連續,說明的確存在了事務丟失,現在的問題就是為什麼 mysql-bin.index 檔案會記錄著有兩個相同 mysql-bin.000006 ,以及客戶的故障場景是如何觸發的。

3.故障復現

3.1.復現 index 索引檔案記錄相同 binlog 檔名

首先根據故障分析的結果,我們先復現出 binlog 索引檔案中 binlog 檔名重複場景。

第一步登入主庫所在的機器,在複製狀態正常下,把主庫正在用的 binlog 日誌 rm 手動刪除。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

第二步進入主庫執行 flush logs 重新整理日誌,這時 binlog 會重新生成剛剛刪除的 binlog 檔案,此時觀察主庫的 binlog 日誌是連續的,index 索引檔案裡面出現了兩個剛剛 rm 手動刪除的 binlog 日誌資訊,即 index 檔案記錄著有兩個相同檔案,與客戶場景一致。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

所以 binlog 索引檔案裡有兩個 binlog.000006 ,通過上面測試可以發現,是因為當正在用的 binlog 檔案被手動rm掉時,binlog 檔案計數器是不會受到影響,當在 binlog 檔案重新整理後(重啟、flush log 、binlog 檔案寫滿等),binlog 檔案計數器會根據當前最大 binlog 檔案+1。正如上面場景第一個 binlog.000006 檔案是正常記錄 binlog.index 中,此時再將 binlog.000006 檔案 rm 掉後,最大的為 binlog 日誌為 000005 ,這時主庫 flush logs ,還會按順序在最大 binlog.00000 5生成第二個 binlog.000006 ,binlog.index 中也出現兩個 binlog.000006 。但主庫實際已經丟失一個 binlog.000006 ,現有的 binlog.000006 和上一個 binlog.000005 的 gtid 也不連續,只是檔名仍連續。

3.2.復現客戶場景 Got fatal error 1236 from master when reading data from binary log: 'Could not open log file'

在 3.1 的測試過程中發現客戶的故障並不是一定會出現,還有其他現象,我們先來複現出客戶場景。

首先需要主從有一定的延遲,如下從庫獲取到主庫 binlog.000006 。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

此時將主庫正在用的 binlog.000007 手動 rm 掉,這時雖然 binlog.000007 已經被刪除,但仍在後臺被主庫佔用,新的 binlog.000007 這時也還沒有重新整理生成,但 index 裡面是有記錄 binlog.000007 的。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

這時當從庫讀取完 binlog.000006 並繼續獲取 binlog 索引檔案裡記錄的 binlog.000007 時,由於此檔案已經被刪除且主庫沒有生成新的 binlog.000007 ,從而複製報錯。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

主從複製故障後,主庫這時其實還在使用著已經刪除的 binlog 檔案,直到觸發flush logs ,這時mysql-bin.index就會出現3.1場景。至此客戶複製故障場景已完全復現出來。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

故障分析 | 手動 rm 掉 binlog 導致主從報錯

3.3其他場景

在復現的過程中發現還會出現其他不同的場景,由於篇幅較長便簡單描述不再詳細展開,有興趣的同學可以自己進行測試。

場景一:
主從不報錯,從庫丟 gtid ,這種場景和上面客戶複製故障的場景一樣都需要有一定的主從延遲,不同點在於當從庫已經讀取完binlog.xxx並繼續獲取binlog索引檔案裡記錄的被rm刪除掉binlog.yyy檔案時,這時主庫已經觸發flush logs生成了新的binlog.yyy,此時從庫io執行緒讀取到了新的binlog.yyy。這種情況下,從庫gtid是不連續的,主從不一致。

場景二:
在主從沒有延遲或者延遲較低的情況下,從庫已經讀取到主庫正在用的binlog.yyy。這時將主庫正在用的binlog.yyy刪除,由於被刪除的binlog.yyy仍在後臺被佔用著,所以在從庫可以看到複製狀態還是正常的。直到主庫binlog檔案在重新重新整理(flush log、binlog檔案寫滿等)生成新的binlog.yyy後,從庫的gtid這時就不在更新,從庫很快報錯1236。

故障分析 | 手動 rm 掉 binlog 導致主從報錯

為什麼在生成新的binlog.yyy後就報錯1236是因為主庫binlog日誌在重新flush生成新的binlog.yyy後,新的binlog.yyy事件是從4開始的,而此時從庫已經應用到舊binlog.yyy事件的位置遠超4,所以導致從庫無法從新的binlog.yyy讀取binlog日誌從而報錯。

4.建議

通過上面的測試可以發現人為rm掉正在用的binlog基本都會導致主從報錯或主從不一致,而一旦出現這種情況除了重做從庫外一般是沒有其他比較好的方法,這樣是不利於資料庫維護,所以建議:

  1. 避免對binlog檔案做壓縮刪除等直接操作,可以通過調整引數修改binlog清理策略.
  2. 需要手工刪除binlog時,可以進入MySQL通過purge命令去刪除。