[MDEV-21117] refine the server binlog-based recovery for semisync Created: 2019-11-21  Updated: 2024-02-07  Resolved: 2024-02-07

Status: Closed
Project: MariaDB Server
Component/s: Replication
Fix Version/s: 10.6.2

Type: Task Priority: Critical
Reporter: Andrei Elkin Assignee: Brandon Nesterenko
Resolution: Fixed Votes: 3
Labels: None

Attachments: Text File recovery_design.txt    
Issue Links:
Blocks
blocks MDEV-11855 Make semisync crash safe with the clu... Open
Duplicate
is duplicated by MDEV-20996 Maxscale auto-failover with semi-sync... Closed
PartOf
includes MDEV-26652 xa transactions binlogged in wrong order Open
Relates
relates to MDEV-21168 Active XA transactions stop slave fro... Closed
relates to MDEV-25395 server recovery hits replication even... Stalled

 Description   

When run after master server crash --tc-heuristic-recover=rollback produces inconsistent server state with binlog still containing transactions that were rolled back by the option.
Such way recovered server may not be used for replication. E.g when such way recovered
ex-master is demoted into slave its binlog state needs further correction to subtract
the rolled back transactions from its binlog status. Otherwise the "new" slave might claim
those transactions as locally present at the (gtid) master-slave connection protocol. At the same time the actual "new" master may never have seen those transactions (because they never arrived at it when it was formerly slave, due to the crash).

This issue should be fixed with refining the recovery procedure with truncating binlog to cut off the prepared rolled back transactions. The method is also known as pioneered by FB
https://percona.community/blog/2018/08/23/question-about-semi-synchronous-replication-answer-with-all-the-details/

Once a transaction reaches the binary logs it should roll forward.



 Comments   
Comment by Sujatha Sivakumar (Inactive) [ 2019-11-22 ]

Observed reported issue on latest 10.1.44

MariaDB [(none)]> use test;
Database changed
MariaDB [test]> create table t ( f int ) engine=innodb;
Query OK, 0 rows affected (0.02 sec)
 
MariaDB [test]> insert into t values (10);
Query OK, 1 row affected (0.01 sec)
 
MariaDB [test]> insert into t values (20);
ERROR 2013 (HY000): Lost connection to MySQL server during query

Crash the server in the middle of commit.
Restart the server with "--tc-heuristic-recover=ROLLBACK"

Observed that the transaction which tried to insert '20' is rolled back in engine.

MariaDB [test]> select * from t;
+------+
| f    |
+------+
|   10 |
+------+

But the binarylog retains the transaction which was rolled back in the engine.
The binlog 'master-bin.000001' is present post recovery

MariaDB [test]> show binlog events;
+-------------------+-----+-------------------+-----------+-------------+---------------------------------------------------+
| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                              |
+-------------------+-----+-------------------+-----------+-------------+---------------------------------------------------+
| master-bin.000001 |   4 | Format_desc       |         1 |         249 | Server ver: 10.1.44-MariaDB-debug, Binlog ver: 4  |
| master-bin.000001 | 249 | Gtid_list         |         1 |         274 | []                                                |
| master-bin.000001 | 274 | Binlog_checkpoint |         1 |         314 | master-bin.000001                                 |
| master-bin.000001 | 314 | Gtid              |         1 |         352 | GTID 0-1-1                                        |
| master-bin.000001 | 352 | Query             |         1 |         457 | use `test`; create table t (f int ) engine=innodb |
| master-bin.000001 | 457 | Gtid              |         1 |         495 | BEGIN GTID 0-1-2                                  |
| master-bin.000001 | 495 | Query             |         1 |         587 | use `test`; insert into t values(10)              |
| master-bin.000001 | 587 | Xid               |         1 |         614 | COMMIT /* xid=7 */                                |
| master-bin.000001 | 614 | Gtid              |         1 |         652 | BEGIN GTID 0-1-3                                  |
| master-bin.000001 | 652 | Query             |         1 |         744 | use `test`; insert into t values(20)              |
| master-bin.000001 | 744 | Xid               |         1 |         771 | COMMIT /* xid=8 */                                |
+-------------------+-----+-------------------+-----------+-------------+---------------------------------------------------+
11 rows in set (0.00 sec)

GTID state is also preserved within a newly created binary log.

MariaDB [test]> show binlog events in 'master-bin.000002';
+-------------------+-----+-------------------+-----------+-------------+--------------------------------------------------+
| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                             |
+-------------------+-----+-------------------+-----------+-------------+--------------------------------------------------+
| master-bin.000002 |   4 | Format_desc       |         1 |         249 | Server ver: 10.1.44-MariaDB-debug, Binlog ver: 4 |
| master-bin.000002 | 249 | Gtid_list         |         1 |         288 | [0-1-3]                                          |
| master-bin.000002 | 288 | Binlog_checkpoint |         1 |         328 | master-bin.000002                                |
| master-bin.000002 | 328 | Stop              |         1 |         347 |                                                  |
+-------------------+-----+-------------------+-----------+-------------+--------------------------------------------------+
4 rows in set (0.00 sec)

1 row in set (0.00 sec)

This results in inconsistent state.

Comment by Sujatha Sivakumar (Inactive) [ 2020-04-01 ]

Hello Andrei,

Can you please review the fix for MDEV-21117.

Build Bot: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.1-sujatha
Patch: https://github.com/MariaDB/server/commit/b62432fc2459a312aaa0e27c0950de3420a34d53

Thank you.

Comment by Andrei Elkin [ 2020-04-14 ]

Part of the review is done. More work is requested.

Comment by Marko Mäkelä [ 2020-04-17 ]

I helped debug the "loss" of binlog position, which boiled down to this extraneous condition at InnoDB startup:

void
recv_recovery_from_checkpoint_finish(void)
/*======================================*/
{
	if (recv_needed_recovery) {
		trx_sys_print_mysql_master_log_pos();
		trx_sys_print_mysql_binlog_offset();
	}

This code would only be invoked if any log records had been written after the latest log checkpoint. But binlog recovery requires that trx_sys_mysql_bin_log_pos be unconditionally initialized.

Comment by Marko Mäkelä [ 2020-04-23 ]

I think that a merge of this to 10.3 is blocked by MDEV-22351.

Comment by Sujatha Sivakumar (Inactive) [ 2020-04-23 ]

Hello Sergei,

Please review the changes for MDEV-21117.

https://github.com/MariaDB/server/commit/1dd06f633315759b359d1772b8b95bc6c8911c19
http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.1-sujatha

Note: binlog_truncate_retry_success.test fails on "kvm_fulltest2" in 10.3+ versions, because of MDEV-22351. It will be address by MDEV-22351 fix.

Thank you

Comment by Andrei Elkin [ 2020-10-23 ]

The 10.1 patch is ready for review, 534ec31c9b6 commit on the HEAD of bb-10.1-andrei.

Comment by Andrei Elkin [ 2020-10-23 ]

serg: bc00529d14a - the new HEAD of bb-10.1-andrei corrects a silly logic flaw

--- a/sql/handler.cc
+++ b/sql/handler.cc
@@ -2052,7 +2052,7 @@ static my_bool xarecover_handlerton(THD *unused, plugin_ref plugin,
           }
 #endif
         }
-        else if (tc_heuristic_recover == TC_HEURISTIC_RECOVER_ROLLBACK)
+        else if (tc_heuristic_recover != TC_RECOVER_BINLOG_TRUNCATE)
         {
 #ifndef DBUG_OFF
           int rc=
@@ -2070,8 +2070,6 @@ static my_bool xarecover_handlerton(THD *unused, plugin_ref plugin,
 #ifdef HAVE_REPLICATION
         else
         {
-          DBUG_ASSERT(tc_heuristic_recover == TC_RECOVER_BINLOG_TRUNCATE);
-
           if (xid_member_replace(info->commit_list, x, info->mem_root))
           {
             info->error= true;

Comment by Andrei Elkin [ 2020-11-26 ]

serg: I did not changed the state back to In-progress, but it was the case for the past time.
Today `b1f9ce4a133` commit is finally BB-approved, and bb-10.2-andrei contains the branch.
Hope to hear from you about the patch rather sooner than just before next release .

Comment by Andrei Elkin [ 2021-01-22 ]

Howdy, Sergei,

the latest patch abd7557d402 HEAD -> bb-10.3-andrei is ready for review.

Comment by Andrei Elkin [ 2021-01-27 ]

serg: As said on slack MDEV-24654 is untied from the semisync. A squashed 159a38ec388 is ready for review.

Comment by Andrei Elkin [ 2021-02-08 ]

serg At testing of the former patches few glitches were eliminated.
ee538938345 HEAD -> bb-10.3-MDEV-21117 is the final commit that sustained aggressive manual testing with multi-engine & unsafe combinations.
It is ready for review.

Comment by Andrei Elkin [ 2021-04-13 ]

Howdy, Sergei.

The patch is ready. It's in
bb-10.3-MDEV-21117 contains a series of commits, which in the git-log order are:

2b4000e3005 (HEAD -> 10.3-MDEV-21117-no_24654, origin/bb-10.3-MDEV-21117) MDEV-25395 server recovery hits replication event checksum error
f9213f3ed95 Discard FD checksum bug related hunks. To recommit separately as MDEV-25395 fixes.
9165d66dc94 Optimization of binlog scan rounds.
b4a09b20da2 Review notes for binlog_commit away of hton.
4bc83b27494 General character review notes addressed. This excludes binlog_commit away of hton.
dc39bd5f3ec Fixed test specific review comments.
e92037989f7 MDEV-21117: refine the server binlog-based recovery for semisync

`e92037989f7` is the base that you reviewed with notes which are addressed in other commits.
The tests, changes related to binlog_commit and optimization of binlog scan, other changes and MDEV-25395 that motivates reading FD for finding out its binlog checksum.

Comment by Andrei Elkin [ 2021-04-15 ]

serg: Fyi, I keep bb-10.3-MDEV-21117 updated with minor fixes to MDEV-21117 and refinements to MDEV-25395 (today's commit to satisfy existing tests). No functional changes are done to neither of the two.

Comment by Andrei Elkin [ 2021-05-26 ]

The patch is ported to 10.6 and is present as two commits
72a59e4b068 - the basic part, at4cc5a3074da - the user XA part (due to MDEV-742).
See bb-10.6_MDEV-21117.

Comment by Andrei Elkin [ 2021-05-26 ]

serg, there were two replies from me that I've not seen your ack on.
Just in case, the 1st one is from

Subject: Re: [Maria-developers] e92037989f7: MDEV-21117: refine the server binlog-based recovery for semisync
To: Sergei Golubchik <serg@mariadb.org>
Cc: Andrei Elkin <andrei.elkin@mariadb.com>, maria-developers@lists.launchpad.net, alice.sherepa@mariadb.com, sujatha.sivakumar@mariadb.com
Date: Tue, 27 Apr 2021 18:03:47 +0300 (4 weeks, 23 hours, 46 minutes ago)

to clarify on a simulation in this part

> in the first review I wrote
>
> this seems to be a rather crude way of faking a partially committed
> transaction. better to crash after the first engine has committed,
> that'd be much more natural.
>
> and you replied
>
> This simulation aimed at (allows for) more complicated recovery time
> event sequences.
> In this case, indeed, crashing by demand is about of the same efforts.
> I can convert to that.
>
> [x]

I had a rather sobering followup, slipped communicating to you though, sorry.

It's actually turns out not to be easy. A sequence of execution events

E1.prepare(trx), E2.prepare(trx), E1.commit(trx), crash

does not make E1 such as Innodb committed persistently in file. At
recovery in E1 trx may be found in prepared state, unless before the
crash I'd do something like Binlog CheckPoint (BCP) notification request
and wait of it.
In this just a selected engine would be requested, unlike in BCP event
case that is generated when both (in this case) have persistently committed.
(That is we even can't involve BCP event to wait for, and the involvement
would require some simulation as well).

So I propose to keep the current method leaving the "honest" crash to
RQG that Alice has been training the patch with.

and the 2nd for ALTERing the slave table
Subject: Re: [Maria-developers] e92037989f7: MDEV-21117: refine the server binlog-based recovery for semisync

>> Actually not need to. There's no crash in the middle of a slave
>> transaction.
>> So it must be a copy-paste leftover.

actually the test crashes both servers (somehow I managed to forget that).

>>
>> [x]
>
> My bad.
>
> [x]

so I am reverting to keep ALTER.

Comment by Andrei Elkin [ 2021-05-27 ]

serg, fyi commit `557ab2992d` "increments" `origin/bb-10.6_MDEV-21117` to address today's review notes (but the cleaner partial commit simulation and the std::pair related).

Comment by Andrei Elkin [ 2021-06-03 ]

The latest notes are addressed. The branch updated:
8e8c80a187c..5319a893b15 HEAD -> bb-10.6_MDEV-21117

Notice 8e8c80a187c also follows the one by Sujatha
8e8c80a187c (origin/bb-10.6_MDEV-21117) MDEV-21117: binlog_truncate_multi_engine.test improvements which covers
the proper partial commit simulation.

Comment by Andrei Elkin [ 2021-06-07 ]

The branch is just forcibly updated
5319a893b15...8bd36afdb40 HEAD -> bb-10.6_MDEV-21117

with kill -SIGUSR2 pid commit and collapsed one for simulating partial commits in
mtr tests; additionally to the collapsing the former (at recovery) simulation's debug_dbug var
is finally gone.

No more changes has been done.

Comment by Andrei Elkin [ 2021-06-08 ]

Merged with the atomic DDL patch.
8bd36afdb40...2b3d1b977dd HEAD -> bb-10.6_MDEV-21117 (forced update)

Comment by Andrei Elkin [ 2021-06-11 ]

Pushed as 6c39eaeb126.

Comment by Andrei Elkin [ 2021-06-11 ]

Documentation is updated with the following diff.

Comment by Michael Widenius [ 2024-02-07 ]

Currently we have a problems with the binary logs:

  • We truncate transactions from the binary log that was already fully written there (and thus may be on the slave)
  • When we truncate a half-written-transaction we don't take into account that a slave may have already got part of it and will reuse the GTID id if reconnecting to a master that died in the middle of writing the transaction to the binary log.

The fix should be:

  • All fully written transactions in the binary log should roll forwards. The half or not written one should do rollback.
  • In case of the master-slave connection closing before the slave gets a full transaction, it should reconnect to the master and ask for the 'transaction after the last fully received GTID.
    Alternatively it could use the last binlog file + position (which should work fine as the master binlog was truncated).
Comment by Andrei Elkin [ 2024-02-07 ]

monty, to the fully written ones, when a server restarts having both rpl_semi_sync_MASTER,SLAVE_enabled, the semisync slave recovery does not check the first of the two. Hence a server intended to be a master, that is having rpl_semi_sync_MASTER_enabled = true rolls back transactions in doubt unnecessarily and possibly harmfully.

That's an issue. It could be trivially fixed with adding the check of rpl_semi_sync_MASTER_enabled and when it's true it would override.

The half-written is an issue only because the slave is reconnecting to a master that passed through the semisync recovery with the intent to become slave (such master may discard from its binlog a transaction being received by slave.
It will disappear when the new rpl_semi_sync_MASTER_enabled-based decision will be implemented.

Comment by Andrei Elkin [ 2024-02-07 ]

monty, I filed MDEV-33424 for this plan which is about 1 line of code.

Generated at Thu Feb 08 09:04:43 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.