摘要：對于該故障的分析，我們要從主從實例相同，但是事務不同的原因入手，該問題猜測與相關，我們針對同步事務的時序做如下分析。接受者被動接收提議者的提議，并記錄和反饋，或?qū)W習達成共識的提議。節(jié)點將的提案信息發(fā)送至組內(nèi)，仍收到了大多數(shù)成員返回。

本文是由愛可生運維團隊出品的「MySQL專欄」系列文章，內(nèi)容來自于運維團隊一線實戰(zhàn)經(jīng)驗，涵蓋MySQL各種特性的實踐，優(yōu)化案例，數(shù)據(jù)庫架構(gòu)，HA，監(jiān)控等，有掃雷功效。
愛可生開源社區(qū)持續(xù)運營維護的小目標：

每周至少推送一篇高質(zhì)量技術(shù)文章

每月研發(fā)團隊發(fā)布開源組件新版

每年1024開源一款企業(yè)級組件
2019年至少25場社區(qū)活動


歡迎大家持續(xù)關注～

MGR作為MySQL原生的高可用方案，它的基于共識協(xié)議的同步和決策機制，看起來也更為先進。吸引了一票用戶積極嘗試，希望通過MGR架構(gòu)解決RPO=0的高可用切換。在實際使用中經(jīng)常會遇到因為網(wǎng)絡抖動的問題造成集群故障，最近我們某客戶就遇到了這類問題，導致數(shù)據(jù)不一致。

問題現(xiàn)象

這是在生產(chǎn)環(huán)境中一組MGR集群，單主架構(gòu)，我們可以看到在相同的GTID86afb16f-1b8c-11e8-812f-0050568912a4:57305280下，本應執(zhí)行相同的事務，但binlog日志顯示不同事務信息。

Primary節(jié)點binlog：

SET @@SESSION.GTID_NEXT= "86afb16f-1b8c-11e8-812f-0050568912a4:57305280"/*!*/;# at 637087357#190125 15:02:55 server id 3136842491 end_log_pos 637087441 Querythread_id=19132957 exec_time=0 error_code=0SET TIMESTAMP=1548399775/*!*/;BEGIN/*!*/;# at 637087441#190125 15:02:55 server id 3136842491 end_log_pos 637087514 Table_map:`world`.`IC_WB_RELEASE` mapped to number 398# at 637087514#190125 15:02:55 server id 3136842491 end_log_pos 637087597 Write_rows: table id 398flags: STMT_END_FBINLOG "n7RKXBP7avi6SQAAABov+SUAAI4BAAAAAAEAB2ljZW50ZXIAFUlDX1FVRVJZX1VTRVJDQVJEX0xP"/*!*/;### INSERT INTO `world`.`IC_WB_RELEASE`### SET

Secondary節(jié)點binlog：

SET @@SESSION.GTID_NEXT= "86afb16f-1b8c-11e8-812f-0050568912a4:57305280"/*!*/;# at 543772830#190125 15:02:52 server id 3136842491 end_log_pos 543772894 Querythread_id=19162514 exec_time=318 error_code=0SET TIMESTAMP=1548399772/*!*/;BEGIN/*!*/;# at 543772894#190125 15:02:52 server id 3136842491 end_log_pos 543772979 Table_map:`world`.`IC_QUERY_USERCARD_LOG` mapped to number 113# at 543772979#190125 15:02:52 server id 3136842491 end_log_pos 543773612 Delete_rows: table id113 flags: STMT_END_FBINLOG "nLRKXBP7avi6VQAAADNRaSAAAHEAAAAAAAEAB2ljZW50ZXIADUlDX1dCX1JFTEVBU0UACw8PEg8"/*!*/;### DELETE FROM `world`.`IC_QUERY_USERCARD_LOG`### WHERE

從以上信息可以推測，primary節(jié)點在這個GTID下對world.IC_WB_RELEASE表執(zhí)行了insert操作事件沒有同步到secondary節(jié)點，secondary節(jié)點收到主節(jié)點的其他事件，造成了數(shù)據(jù)是不一致的。當在表IC_WB_RELEASE發(fā)生delete操作時，引發(fā)了下面的故障，導致從節(jié)點脫離集群。

2019-01-28T11:59:30.919880Z 6 [ERROR] Slave SQL for channel "group_replication_applier": Could not execute Delete_rows event on table `world`.`IC_WB_RELEASE`; Can"t find record in "IC_WB_RELEASE", Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND, Error_code: 10322019-01-28T11:59:30.919926Z 6 [Warning] Slave: Can"t find record in "IC_WB_RELEASE" Error_code: 10322019-01-28T11:59:30.920095Z 6 [ERROR] Plugin group_replication reported: "The applier thread execution was aborted. Unable to process more transactions, this member will now leave the group."2019-01-28T11:59:30.920165Z 6 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log "FIRST" position 271.2019-01-28T11:59:30.920220Z 3 [ERROR] Plugin group_replication reported: "Fatal error during execution on the Applier process of Group Replication. The server will now leave the group."2019-01-28T11:59:30.920298Z 3 [ERROR] Plugin group_replication reported: "The server was automatically set into read only mode after an error was detected."

問題分析

主節(jié)點在向從節(jié)點同步事務時，至少有一個GTID為86afb16f-1b8c-11e8-812f-0050568912a4:57305280（執(zhí)行的是insert操作）的事務沒有同步到從節(jié)點，此時從實例還不存在這個GTID；于是主實例GTID高于從實例。數(shù)據(jù)就已經(jīng)不一致了。

集群業(yè)務正常進行，GTID持續(xù)上漲，新上漲的GTID同步到了從實例，占用了86afb16f-1b8c-11e8-812f-0050568912a4:57305280這個GTID，所以從實例沒有執(zhí)行insert操作，少了一部分數(shù)據(jù)。

主節(jié)點對GTID為86afb16f-1b8c-11e8-812f-0050568912a4:57305280執(zhí)行的insert數(shù)據(jù)進行delete，而從節(jié)點由于沒有同步到原本的insert操作；沒有這部分數(shù)據(jù)就不能delete，于是脫離了集群。

對于該故障的分析，我們要從主從實例GTID相同，但是事務不同的原因入手，該問題猜測與bug（https://bugs.mysql.com/bug.ph...）相關，我們針對MGR同步事務的時序做如下分析。

相關知識背景

MGR全組同步數(shù)據(jù)的Xcom組件是基于paxos算法的實現(xiàn)；每當提交新生事務時，主實例會將新生事務發(fā)送到從實例進行協(xié)商，組內(nèi)協(xié)商通過后全組成員一起提交該事務；每一個節(jié)點都以同樣的順序，接收到了同樣的事務日志，所以每一個節(jié)點以同樣的順序回放了這些事務，最終組內(nèi)保持了一致的狀態(tài)。

paxos包括兩個角色：

提議者（Proposer）：主動發(fā)起投票選主，允許發(fā)起提議。
接受者（Acceptor）：被動接收提議者（Proposer）的提議，并記錄和反饋，或?qū)W習達成共識的提議。

paxos達成共識的過程包括兩個階段：

第一階段（prepare）

a：提議者（Proposer）發(fā)送prepare請求，附帶自己的提案標識（ballot，由數(shù)值編號加節(jié)點編號組成）以及value值。組成員接收prepare請求；b：如果自身已經(jīng)有了確認的值，則將該值以ack_prepare形式反饋；在這個階段中，Proposer收到ack回復后會對比ballot值，數(shù)值大的ballot會取代數(shù)值小的ballot。如果收到大多數(shù)應答之后進入下一個階段。

第二階段（accept）

a：提議者（Proposer）發(fā)送accept請求
b：接收者（Acceptor）收到請求后對比自身之前的bollat是否相同以及是否接收過value值。如果未接受過value值 以及ballot相同，則返回ack_accept，如果接收過value值，則選取最大的ballot返回ack_accept。c：之后接受相同value值的Proposer節(jié)點發(fā)送learn_op，收到learn_op節(jié)點的實例表示確認了數(shù)據(jù)修改，傳遞給上層應用。

針對本文案例我們需要強調(diào)幾個關鍵點：

1.該案例最根本的異常對比發(fā)生在第二次提案的prepare階段。

2.prepare階段的提案標識由數(shù)值編號和節(jié)點編號兩部分組成；其中數(shù)值編號類似自增長數(shù)值，而節(jié)點編號不變。

分析過程

結(jié)合paxos時序，我們對案例過程進行推測：

Tips：以下分析過程請結(jié)合時序圖操作步驟觀看

建議點開放大，效果更清晰 ^ ^

【step1】primary節(jié)點要執(zhí)行對表world.IC_WB_RELEASE的insert操作，向組內(nèi)發(fā)送假設將ballot設置為（0.0）以及將value值world.IC_WB_RELEASE的prepare請求，并收到大多數(shù)成員的ack_prepare返回，于是開始發(fā)送accept請求。primary節(jié)點將ballot（0.0）的提案信息發(fā)送至組內(nèi)，仍收到了大多數(shù)成員ack_accept（ballot=0.0value=world.IC_WB_RELEASE）返回。然后發(fā)送learn_op信息【step3】。

同時其他從節(jié)點由于網(wǎng)絡原因沒有收到主實例的的learn_op信息【step3】，而其中一臺從實例開始新的prepare請求【step2】，請求value值為no_op（空操作）ballot=1.1（此編號中節(jié)點編號是關鍵，該secondary節(jié)點編號大于primary節(jié)點編號，導致了后續(xù)的問題，數(shù)值編號無論誰大誰小都要被初始化）。

其他的從實例由于收到過主節(jié)點的value值；所以將主節(jié)點的（ballot=0.0，value=world.IC_WB_RELEASE）返回；而收到的ack_prepare的ballot值的數(shù)值符號全組內(nèi)被初始化為0，整個ballot的大小完全由節(jié)點編號決定，于是從節(jié)點選取了ballot較大的該實例value值作為新的提案，覆蓋了主實例的value值并收到大多數(shù)成員的ack_accept【step2】。并在組成員之間發(fā)送了learn_op信息【step3】，跳過了主實例提議的事務。

從源碼中可以看到關于handle_ack_prepare的邏輯。

handle_ack_prepare has the following code:    if (gt_ballot(m->proposal,p->proposer.msg->proposal))        {            replace_pax_msg(&p->proposer.msg, m);            ...            }

此時，主節(jié)點在accept階段收到了組內(nèi)大多數(shù)成員的ack_accept并收到了 自己所發(fā)送的learn_op信息，于是把自己的提案（也就是binlog中對表的insert操作）提交【step3】，該事務GTID為86afb16f-1b8c-11e8-812f-0050568912a4:57305280。而其他節(jié)點的提案為no_op【step3】，所以不會提交任何事務。此時主實例GTID大于其他從實例的。

主節(jié)點新生GTID繼續(xù)上漲；同步到從實例，占用了從實例的86afb16f-1b8c-11e8-812f-0050568912a4:57305280這個GTID，于是產(chǎn)生了主節(jié)點與從節(jié)點binlog中GTID相同但是事務不同的現(xiàn)象。

當業(yè)務執(zhí)行到對表world.IC_WB_RELEASE的delete操作時，主實例能進行操作，而其他實例由于沒有insert過數(shù)據(jù)，不能操作，就脫離了集群。

▽過程總結(jié)：

舊主發(fā)送prepare請求，收到大多數(shù)ack，進入accept階段，收到大多數(shù)ack。

從實例由于網(wǎng)絡原因沒有收到learn_op信息。

其中一臺從實例發(fā)送新的prepare請求，value為no_op。

新一輪的prepare請求中，提案標識的數(shù)值編號被初始化，新的提案者大于主實例，從實例選取新提案，執(zhí)行空操作，不寫入relay-log。代替了主實例的事務，使主實例GTID大于從實例。

集群網(wǎng)絡狀態(tài)恢復，新生事物正常同步到從實例，占用了本該正常同步的GTID，使集群中主節(jié)點與從節(jié)點相同GTID對應的事務時不同的。

結(jié)論

針對此問題我們也向官方提交SR，官方已經(jīng)反饋社區(qū)版MySQL 5.7.26和MySQL 8.0.16 中會修復，如果是企業(yè)版客戶可以申請最新的hotfix版本。

在未升級 MySQL 版本前，若再發(fā)生此類故障，在修復時需要人工檢查，檢查切換時binlog中 GTID 信息與新主節(jié)點對應 GTID 的信息是否一致。如果不一致需要人工修復至一致狀態(tài)，如果一致才可以將被踢出的原主節(jié)點加回集群。

所以正在使用了MGR 5.7.26之前社區(qū)版的DBA同學請注意避坑。

開源分布式中間件DBLE
社區(qū)官網(wǎng)：https://opensource.actionsky....
GitHub主頁：https://github.com/actiontech...
技術(shù)交流群：669663113

開源數(shù)據(jù)傳輸中間件DTLE
社區(qū)官網(wǎng)：https://opensource.actionsky....
GitHub主頁：https://github.com/actiontech...
技術(shù)交流群：852990221