Orchestrator promotes a replica with lag on Mariadb

[mohankara]

We have a 3 node MariaDB 10.5.10 setup on Centos. 1 Primary and 2 replicas with semi-sync enabled.
Our current orchestrator version is 3.2.4

We had a scenario where the replicas were lagging by few hours, master was not reachable so one of the replicas was promoted as primary in spite of the huge lag. This resulted in a data loss. Ideally orchestrator should wait for the replica's relay logs to be applied on the replica then promote as a master. This seems to be the behavior on MySQL based on my testing but not on Mariadb.

--Test case:
Tests against MySQL and Mariadb are done with these orchestrator parameters in /etc/orchaestrator.conf.json

"DelayMasterPromotionIfSQLThreadNotUpToDate": true,
"debug": true

Restart orchestrator on all 3 nodes
I)Test on MariaDB:
Start a 3 node Mariadb cluster (Semi-sync enabled)
1.Create and add data to a test table
create table test (colA int, colB int, colC datetime, colD int);

insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
insert into test values (rand()*100,rand()*1000,now(),rand()*10000);

2. Stop slave SQL_THREAD on replicas (Node 2, 3)

3. Wait for few secs and add some more data to Node 1 (master)
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);
   insert into test values (rand()*100,rand()*1000,now(),rand()*10000);

4. Stop mysqld on Master (Node 1)

5. You will see the orchestrator promoting a replica without the data added in Step Rqlite bin #3.

Test on MySQL 5.7.32:
Repeat the same test on 3 node MySQL
You will notice orchestrator promoting one of the replicas with out any data loss ie seeing 14 rows !!!

Thank You
Mohan

[shlomi-noach]

This PR goes at least halfway though: #1366

Question: in your actual production incident, was SQL_thread running at time of failover, to the best of your knowledge?

[mohankara]

In 1 case it was running but behind, in another it was down due to an error. In both cases the replica was wrongly promoted.

[mohankara]

Any ETA on when the fix will be available ? We have few sites that experience this issue.

[shlomi-noach]

I hope to reproduce this week.

[mohankara]

I hope to reproduce this week.

Thanks Shlomi. I am looking forward to it.

[shlomi-noach]

I followed the reproduction steps, but this does not reproduce for me: both replicas apply the relay log and then get promoted. I'm using current master branch.
This was very manual. I'll need to set up something more automated so I can test again and again and again. I need to think about how to do that without exhausting my resources.

[mohankara]

I followed the reproduction steps, but this does not reproduce for me: both replicas apply the relay log and then get promoted. I'm using current master branch.
That's what we want correct ? Is this with your new fixes in place or with 3.2.4 ?

This was very manual. I'll need to set up something more automated so I can test again and again and again. I need to think about how to do that without exhausting my resources.
This issue happens only with Mariadb. MySQL works fine. I have some cycles for testing if I can be of any assistance to you.

[shlomi-noach]

This issue happens only with Mariadb. MySQL works fine. I have some cycles for testing if I can be of any assistance to you.

Yes, of course. I used MariaDB 10.5.10, same as reported.

[shlomi-noach]

I'll continue early next week. This week is increasingly busy

[shiweng]

This issue happens only with Mariadb. MySQL works fine. I have some cycles for testing if I can be of any assistance to you.

Yes, of course. I used MariaDB 10.5.10, same as reported.

hi,may be I have similar issues,
Orchestrator version: 3.0.14
mysql version: mysql-community-8.0.19
a replication cluster with 1 master and 2 slaves,use pt-heartbeat as slowquery monitor, and I set following parameters:
DelayMasterPromotionIfSQLThreadNotUpToDate: true
FailMasterPromotionIfSQLThreadNotUpToDate: false
FailMasterPromotionOnLagMinutes:0

when both slaves were lag behind master for more than 60 seconds, I issue "shutdown;" on master, and I hope orchestrator will wait for one of slaves sqlthreaduptodate with master, then begin a promotion.however, promotion begin immediately when master gone,so promoted slave will lost some transactions. this is not what we are expected.

now,I have to set parameters on my production environment:
DelayMasterPromotionIfSQLThreadNotUpToDate: false
FailMasterPromotionIfSQLThreadNotUpToDate: true
FailMasterPromotionOnLagMinutes:0

with these settings, promotion will fail when all slaves are lag behind with master.
will you do me a favor,thanks.

by the way, I use sysbench to simulate pressure on master,and I set "set global binlog_group_commit_sync_delay=20000;" on slaves to simulate lags.

[mohankara]

This issue happens only with Mariadb. MySQL works fine. I have some cycles for testing if I can be of any assistance to you.

Yes, of course. I used MariaDB 10.5.10, same as reported.

hi,may be I have similar issues,
Orchestrator version: 3.0.14
mysql version: mysql-community-8.0.19
a replication cluster with 1 master and 2 slaves,use pt-heartbeat as slowquery monitor, and I set following parameters:
DelayMasterPromotionIfSQLThreadNotUpToDate: true
FailMasterPromotionIfSQLThreadNotUpToDate: false
FailMasterPromotionOnLagMinutes:0

when both slaves were lag behind master for more than 60 seconds, I issue "shutdown;" on master, and I hope orchestrator will wait for one of slaves sqlthreaduptodate with master, then begin a promotion.however, promotion begin immediately when master gone,so promoted slave will lost some transactions. this is not what we are expected.

now,I have to set parameters on my production environment:
DelayMasterPromotionIfSQLThreadNotUpToDate: false
FailMasterPromotionIfSQLThreadNotUpToDate: true
FailMasterPromotionOnLagMinutes:0

with these settings, promotion will fail when all slaves are lag behind with master.
will you do me a favor,thanks.

by the way, I use sysbench to simulate pressure on master,and I set "set global binlog_group_commit_sync_delay=20000;" on slaves to simulate lags.

I couldn't simulate this issue (replica getting promoted as master while there is lag) on MySQL 5.7. But I was using orchestrator 3.2.4. I know there are fixes related to this issue in 3.2.4. Try that version or 3.2.5 and see. Hope that works for you.

[shlomi-noach]

Gonna clear some time tomorrow for testing.

[shlomi-noach]

Can you please share your MariaDB config? Also, a SHOW SLAVE STATUS on any of the replicas?

[shlomi-noach]

I'm able to reproduce.

[shlomi-noach]

OK this is does after all circles back to the surprising behavior on MariaDB, explained in #1260 (comment).

As it turns out, when a replica cannot connect to its master/primary, and tries to reconnect, it resets the value of Read_Master_Log_Pos. To illustrate and to explain why it matters, consider this scenario:

1. MariaDB primary + 2 replicas in GTID=current_pos and with semi sync enabled with "infinite" timeout
2. We create a table on the primary, insert one row
3. all 3 nodes show that one row
4. we stop slave sql_thread on both replicas
5. we insert 2nd row on the primary
6. since sql_thread on replicas is still working, they both pull the binlog event, acking to the primary
7. the primary now has 2 rows, but both replicas have 1 row.

At this time the coordinates on my test env show:

mysql -e "show slave status\G" | grep Master_Log

output on both replicas:

           Read_Master_Log_Pos: 3985
         Relay_Master_Log_File: mysql_sandbox22511-bin.000001
           Exec_Master_Log_Pos: 3784
---
               Master_Log_File: mysql_sandbox22511-bin.000001
           Read_Master_Log_Pos: 3985
         Relay_Master_Log_File: mysql_sandbox22511-bin.000001
           Exec_Master_Log_Pos: 3784

which makes perfect sense. The primary has advanced as far as pos=3985 but both replicas are only caught up as far as 3784.

Now, we stop the primary. Whatever it is that orchestrator does during promotion, we then see (right before actual promotion):

               Master_Log_File: mysql_sandbox22513-bin.000001
           Read_Master_Log_Pos: 3768
         Relay_Master_Log_File: mysql_sandbox22513-bin.000001
           Exec_Master_Log_Pos: 3768
---
               Master_Log_File: mysql_sandbox22511-bin.000001
           Read_Master_Log_Pos: 3784
         Relay_Master_Log_File: mysql_sandbox22511-bin.000001
           Exec_Master_Log_Pos: 3784

Notice how in both replicas, the value of Read_Master_Log_Pos is decreased from 3985... 💥
So the replicas forget that they were ahead in replication. They forget that they were supposed to track a certain position.
And that's why the failover in MariaDB behaves differently than in MySQL.

Anyway, we're here to solve this. I thought #1264 should have solved it, but apparently there's seemingly someplace else where orchestrator restarts IO_THREAD on the replicas. So I'm gonna try and find where that happens and take it from there.