作者：陳偉
愛可生資料庫工程師，負責MySQL日常維護及故障處理。
本文來源：原創投稿
*愛可生開源社群出品，原創內容未經授權不得隨意使用，轉載請聯絡小編並註明來源。
1.故障描述
前一段時間客戶反饋複製報錯 1236 ，根據報錯提示該報錯為從庫讀取到了主庫不存在的 binlog 日誌，導致複製中斷，報錯截圖如下，需要幫忙分析為什麼會報錯 Could not open log file 原因。
2.故障分析
說明：考慮客戶資訊敏感性，以下分析過程均在測試環境模擬，資料庫版本 5.7.31 ，GTID 啟用。
2.1.先登入從庫檢視報錯資訊
發現從庫的 io 執行緒斷了，並報錯：Got fatal error 1236 from master when reading data from binary log: 'Could not open log file' ，從字面意思不難理解，無法從主庫獲取到 binlog 日誌，GTID 停止在 828415 ，檢查從庫 error 日誌報錯如下：
根據從庫報錯資訊，下一步我們去主庫檢視主庫的 binlog 資訊和 error 日誌，看主庫 binlog 是否有丟失的情況。
2.2.檢視主庫 binlog 資訊，以及 error 日誌
登入主庫檢查 binlog 日誌列表以及 index 索引檔案，發現主庫的 binlog 是連續的沒有問題，但在檢視 mysql-bin.index 檔案的時候發現有記錄兩個 mysql-bin.000006 ，但是實際只有一個 mysql-bin.000006 檔案，先記著這個奇怪的現象。
再去看一眼主庫的 error 日誌，內容如下，和從庫 error 日誌都指向同一個 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 的位置。
繼續解析 mysql-bin.000006 檢視其第一個事務的 gtid 為：'c582a82e-b985-11ec-adf5-02000aba3e89:855706' 。
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 手動刪除。
第二步進入主庫執行 flush logs 重新整理日誌，這時 binlog 會重新生成剛剛刪除的 binlog 檔案，此時觀察主庫的 binlog 日誌是連續的，index 索引檔案裡面出現了兩個剛剛 rm 手動刪除的 binlog 日誌資訊，即 index 檔案記錄著有兩個相同檔案，與客戶場景一致。
所以 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 。
此時將主庫正在用的 binlog.000007 手動 rm 掉，這時雖然 binlog.000007 已經被刪除，但仍在後臺被主庫佔用，新的 binlog.000007 這時也還沒有重新整理生成，但 index 裡面是有記錄 binlog.000007 的。
這時當從庫讀取完 binlog.000006 並繼續獲取 binlog 索引檔案裡記錄的 binlog.000007 時，由於此檔案已經被刪除且主庫沒有生成新的 binlog.000007 ，從而複製報錯。
主從複製故障後，主庫這時其實還在使用著已經刪除的 binlog 檔案，直到觸發flush logs ，這時mysql-bin.index就會出現3.1場景。至此客戶複製故障場景已完全復現出來。
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。
為什麼在生成新的binlog.yyy後就報錯1236是因為主庫binlog日誌在重新flush生成新的binlog.yyy後，新的binlog.yyy事件是從4開始的，而此時從庫已經應用到舊binlog.yyy事件的位置遠超4，所以導致從庫無法從新的binlog.yyy讀取binlog日誌從而報錯。
4.建議
通過上面的測試可以發現人為rm掉正在用的binlog基本都會導致主從報錯或主從不一致，而一旦出現這種情況除了重做從庫外一般是沒有其他比較好的方法，這樣是不利於資料庫維護，所以建議：
- 避免對binlog檔案做壓縮刪除等直接操作，可以通過調整引數修改binlog清理策略.
- 需要手工刪除binlog時，可以進入MySQL通過purge命令去刪除。