Page MenuHomePhabricator

ROW-based replicas broke with cleaned up heartbeat tables after setting up circular replication
Closed, ResolvedPublic

Description

While the automation worked correctly for STATEMENT based replica sets, the primary master replication broke on ROW, because it complained with:

Slave_SQL_Running: No
Last_Error: Could not execute Update_rows_v1 event on table heartbeat.heartbeat; Can't find record in 'heartbeat', Error_code: 1
log
Sep 18 21:27:14 db1220 mysqld[5222]: 2024-09-18 21:27:14 658112927 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='db2196.codfw.wmnet', master_port='3306', master_log_file='db2196-bin.003331', master_log_pos='299799413'.
Sep 18 21:27:15 db1220 mysqld[5222]: 2024-09-18 21:27:15 658112939 [Note] Slave I/O thread: Start asynchronous replication to master 'repl2024@db2196.codfw.wmnet:3306' in log 'db2196-bin.003331' at position 299799413
Sep 18 21:27:15 db1220 mysqld[5222]: 2024-09-18 21:27:15 658112939 [Note] Slave I/O thread: connected to master 'repl2024@db2196.codfw.wmnet:3306',replication started in log 'db2196-bin.003331' at position 299799413
Sep 18 21:27:17 db1220 mysqld[5222]: 2024-09-18 21:27:17 658112940 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table heartbeat.heartbeat; Can't find record in 'heartbeat', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log db2196-bin.003331, end_log_pos 299800037, Gtid 180360966-180360966-41321649, Internal MariaDB error code: 1032
Sep 18 21:27:17 db1220 mysqld[5222]: 2024-09-18 21:27:17 658112940 [Warning] Slave: Can't find record in 'heartbeat' Error_code: 1032
Sep 18 21:27:17 db1220 mysqld[5222]: 2024-09-18 21:27:17 658112940 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'db2196-bin.003331' position 299799413
Sep 18 21:27:17 db1220 mysqld[5222]: 2024-09-18 21:27:17 658112940 [Note] Slave SQL thread exiting, replication stopped in log 'db2196-bin.003331' at position 299799413, master: db2196.codfw.wmnet:3306

This is due to, once the secondary master starts pt-heartbeat-wikimedia, it generates an SQL REPLACE on the secondary, which gets written as a row_update into the ROW format binlog. The row, missing in the primary master, fails to be inserted, as it wants to update an existing row, not insert it. This doesn't affect STATEMENT masters as the REPLACE is kept, and it inserts or updates depending on the replica set automatically.

There are several options to overcome this, from switching to statement, to deleting the table fully to preinserting the row, but why did it used to work before? Was the row not used to be cleaned? Was there a special procedure before?

Event Timeline

ABran-WMF reopened this task as Open.
ABran-WMF triaged this task as Medium priority.
ABran-WMF moved this task from Triage to Refine on the DBA board.

Not resolved- this is a blocker for switchover, and we haven't yet fixed it for future runs. This is an outstanding issue and we need to do something about it, even if it is no longer happening.

Change #1074127 had a related patch set uploaded (by Volans; author: Volans):

[operations/cookbooks@master] sre.switchdc.databases.prepare: add check

https://gerrit.wikimedia.org/r/1074127

ABran-WMF moved this task from Refine to In progress on the DBA board.
ABran-WMF moved this task from Todo to Doing on the Data-Persistence-Automations board.

There are several options to overcome this, from switching to statement, to deleting the table fully to preinserting the row, but why did it used to work before?

I think the best way would be to preinsert the row in the cookbook. Maybe there is some heartbeat savvy that I'm missing to realize there is a better way to tackle this, but I'm not feeling comfortable with the idea of dropping the table entirely.

Was the row not used to be cleaned? Was there a special procedure before?

I'm not sure how this was done before, I have found no documentation or log about this. Maybe I missed something?

Not resolved- this is a blocker for switchover, and we haven't yet fixed it for future runs. This is an outstanding issue and we need to do something about it, even if it is no longer happening.

Do you think an approach is better than another? Given the remaining time before switchover, I think we should try to aim for the simplest solution.

Given the remaining time before switchover

This is not something we need to fix before the switchover, it was manually workarounded, and it is not a blocker for it. It is a blocker for the next switchover. Circular replication was setup.

This may only be fully resolved until Manuel returns. This is just the post-incident task to ensure we avoid it happening again.

What we can give it is a preliminary solution, but it doesn't have to be before the switchover, it only has to happen before the next switchover.

So this is my request for you @Volans, this is the best thing I think we can do now:

  • Additional check at the start of the script (before touching anything, during initial validation) checking the servers row format:
mysql> SELECT @@GLOBAL.binlog_format;
+------------------------+
| @@GLOBAL.binlog_format |
+------------------------+
| MIXED                  |
+------------------------+
1 row in set (0.001 sec)

mysql> SHOW GLOBAL VARIABLES like 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | MIXED |
+---------------+-------+
1 row in set (0.002 sec)

I think the first method would be preferred.

There can be 3 values returned: "MIXED", "ROW" or "STATEMENT". These haven't changed since 2007, although MySQL has deprecated those (it would be nice to failback to ROW if the variable doesn't exist).

If binlog format on server_from != server_to, abort (bad state, we want the same format on both).
If the same, store it on memory for later.

This is safe to do it in dry mode.

  • Before setting up replication in the direction server_from <- server_to:

If binlog_format != "STATEMENT" and the row doesn't exist (returns 0 results) on the server (query: heartbeat database on server_from, like this:

SELECT * FROM heartbeat WHERE server_id = <server_id_to>;

)

: Insert a new row with server_id the server_to id in the heartbeat database of server_from, with replication enabled, like this:

REPLACE INTO heartbeat (ts, server_id, file, position, relay_master_log_file, exec_master_log_pos, shard, datacenter) VALUES (now(6), <server_id_to>, '', 0, '', 0, '<section_name>', 'server_to_dc');

We should try to minimize the time between the insertion and the restart of heartbeat on the server_to.

It is safe to insert it on a STATEMENT replication, and even if the row existed, but we would prefer not having to do it if we were on those cases (less moving parts).


Those can be 2 separate patches, the checks would happen as usual (including replication is flowing at the end). The cleanup would happen anyway, no need to do anythings special on finish.

I will check those by testing with ROW format in test-s4.

Thanks @jcrespo for the detailed request. I'll get to it. Only one question, are you sure we want to use REPLACE and not INSERT? I thought that replace contributed to the issue.

Yes, the REPLACE is not the issue, it is ROW that translates it to UPDATE or DELETE + INSERT, but those would cause the same issues if doing it in the wrong case (but will do the right thing if the row was to be inserted randomly after select). We want to do replace, even if we did INSERT ignore, it won't fix things for replicas, the issue is ROW behavior, not the query itself.

Change #1079536 had a related patch set uploaded (by Volans; author: Volans):

[operations/cookbooks@master] sre.switchdc.databases.prepare: fix heartbeat

https://gerrit.wikimedia.org/r/1079536

Change #1079537 had a related patch set uploaded (by Volans; author: Volans):

[operations/cookbooks@master] sre.switchdc.databases: allow to select a section

https://gerrit.wikimedia.org/r/1079537

@jcrespo I had it almost finished yesterday but then I had to step out, I've sent the patches. If you test with the test-cookbook using as CR the last one (1079537) you'll be also testing all the other pending improvements that were done but not yet merged.
The last one allows to test it also on a custom section, so you can pass --section test-s4 and it should do the right thing.

$ test-cookbook -c 1079537 --dry-run sre.switchdc.databases.prepare --section test-s4 -t T375144 eqiad codfw
...
DRY-RUN: MASTER_TO db2230.codfw.wmnet Ignoring MASTER STATUS is not stable in DRY-RUN
DRY-RUN: [test-s4] Binlog format is STATEMENT. No heartbeat corrective action needed.
DRY-RUN: [test-s4] MASTER_FROM db1125.eqiad.wmnet CHANGE MASTER to ReplicationInfo(primary='db2230.codfw.wmnet', binlog='db2230-bin.000005', position=201650676, port=3306)
DRY-RUN: MASTER_FROM db1125.eqiad.wmnet CHANGE MASTER to ReplicationInfo(primary='db2230.codfw.wmnet', binlog='db2230-bin.000005', position=201650676, port=3306) and user repl2024
DRY-RUN: Executing commands ['/usr/local/bin/mysql --socket /run/mysqld/mysqld.sock --batch --execute "START SLAVE"'] on 1 hosts: db1125.eqiad.wmnet
DRY-RUN: MASTER_FROM db1125.eqiad.wmnet START SLAVE
DRY-RUN: MASTER_FROM db1125.eqiad.wmnet skipping replication from MASTER_TO db2230.codfw.wmnet verification
DRY-RUN: Executing commands ['/bin/systemctl start pt-heartbeat-wikimedia.service'] on 1 hosts: db2230.codfw.wmnet
DRY-RUN: MASTER_TO db2230.codfw.wmnet started pt-heartbeat.
DRY-RUN: Executing commands ['/usr/local/bin/mysql --socket /run/mysqld/mysqld.sock --batch --execute "START SLAVE"'] on 1 hosts: db2230.codfw.wmnet
DRY-RUN: MASTER_TO db2230.codfw.wmnet START SLAVE.
DRY-RUN: Executing commands ['/usr/local/bin/mysql --socket /run/mysqld/mysqld.sock --batch --execute "SHOW SLAVE STATUS\\G"'] on 1 hosts: db2230.codfw.wmnet
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Master_Host=db1125.eqiad.wmnet
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Master_User=repl2024
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Master_Port=3306
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Slave_IO_Running=Yes
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Slave_SQL_Running=Yes
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Last_IO_Errno=0
DRY-RUN: [test-s4] MASTER_TO db2230.codfw.wmnet checking SLAVE STATUS Last_SQL_Errno=0
DRY-RUN: MASTER_TO db2230.codfw.wmnet replication from MASTER_FROM db1125.eqiad.wmnet verified
DRY-RUN: Executing commands ['/usr/local/bin/mysql --socket /run/mysqld/mysqld.sock --batch --execute "SHOW SLAVE STATUS\\G"'] on 1 hosts: db1125.eqiad.wmnet
DRY-RUN: Failed to run cookbooks.sre.switchdc.databases.prepare.PrepareSection.master_from_check_replication: SHOW SLAVE STATUS seems to have been executed on a master.
DRY-RUN: Traceback
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/wmflib/interactive.py", line 183, in confirm_on_failure
    ret = func(*args, **kwargs)
  File "/home/jynus/cookbooks_testing/cookbooks/cookbooks/sre/switchdc/databases/prepare.py", line 331, in master_from_check_replication
    status = self.master_from.show_slave_status()
  File "/usr/lib/python3/dist-packages/spicerack/mysql_legacy.py", line 201, in show_slave_status
    raise MysqlLegacyError(f"{sql} seems to have been executed on a master.")
spicerack.mysql_legacy.MysqlLegacyError: SHOW SLAVE STATUS seems to have been executed on a master.
==> What do you want to do? "retry" the last command, manually fix the issue and "skip" the last command to continue the execution or completely "abort" the execution.
>

I am not sure if the dry run is doing too much or if the expectations on dry-run need special handling?

I need to research more line 255 change:

self._validate_slave_status(f"MASTER_TO {self.master_to.host}", status, expected)

The cause of that dry-run failure was the added check of replication working of MASTER_FROM from MASTER_TO added here

I've updated the CR to skip the step like we do already here .

See the updated diff

Thanks Riccardo, as I said on IRC it looked like a minor issue so I wasn't too worried, and it was. Your are very fast at this, so big ❤ to you. Will continue testing, probably tomorrow morning.

Change #1081103 had a related patch set uploaded (by Jcrespo; author: Jcrespo):

[operations/puppet@production] mariadb: Default pt-heartbeat STATEMENT-based replication

https://gerrit.wikimedia.org/r/1081103

The (potential) change that caused it was: https://gerrit.wikimedia.org/r/c/operations/puppet/+/693162

But the idea of that is fine (changing tendril db, which we don't care much about). Was there some other hiera key lost since then that affected es and x1?

...

Then there is this, which is probably not in the right direction, but shouldn't had affected the other hosts (or tendril, given it would have been decommissioned by then): https://phabricator.wikimedia.org/rOPUP24cfa58329d2d797542ba8b7f04e636b5d295d8a

Git log doesn't show any other changes on hiera for ROW, so I think 693162 is the original cause, which is very very weird without any default hiera keys (changes x1 and es behaviour).

Change #1074127 merged by jenkins-bot:

[operations/cookbooks@master] sre.switchdc.databases.prepare: add check

https://gerrit.wikimedia.org/r/1074127

Let's merge carefully https://gerrit.wikimedia.org/r/1081103 early next week (so we can monitor not affecting production hosts) CC @Ladsgroup @ABran-WMF

Change #1079536 merged by jenkins-bot:

[operations/cookbooks@master] sre.switchdc.databases.prepare: add binlog check

https://gerrit.wikimedia.org/r/1079536

Change #1079537 merged by jenkins-bot:

[operations/cookbooks@master] sre.switchdc.databases: allow to select a section

https://gerrit.wikimedia.org/r/1079537

Change #1081103 merged by Jcrespo:

[operations/puppet@production] mariadb: Default pt-heartbeat to STATEMENT-based replication

https://gerrit.wikimedia.org/r/1081103

Deployment went well, I will update the incident doc with the long-term fix and then call this resolved.

es6, es7 and x1 keep using ROW-based replication but pt-heartbeat-wikimedia overrides using STATEMENT, which should be used everywhere.