mariadb/mysql-test/suite/rpl/t/rpl_heartbeat_at_rotate.test
Brandon Nesterenko a394fc0270 MDEV-29981: Replica stops with "Found invalid event in binary log"
Replication can stop in error if a Heartbeat log event is sent to a
replica during rotation. There are two bugs at play:

  1. Prior to MDEV-30128 (added in 11.0), there is a bug when checking
     legacy events. When the replica rotates its relay logs, it
     initializes its Format_description_log_event with binlog version 3
     (this is hard-coded). So immediately after rotation (and until a
     new Format_descriptor with binlog_format 4 is sent from the
     master), the IO thread is expecting binlog_format 3 (i.e. it will
     call queue_old_event() for incoming events). This invalidates any
     events that are sent with an event type higher than 14. In theory,
     we wouldn't expect any events to be sent in-between a rotate and
     the next format descriptor log event, but if a long enough period
     of time passes between then, the primary will generate and send a
     Heartbeat event (of type 27). In such case, the slave will see the
     heartbeat event of type 27, see it is higher than 14, and result
     in an error mentioning 'Found invalid event in binary log', with
     the expected log coordinates of the new log (which is
     optimistically populated from the Rotate log event, not the new
     event).

  2. In all versions of MariaDB (11.0+), there is a bug when checking
     the state of a Heartbeat log event, in that it doesn't consider a
     rotated binary log. The check is meant to ensure that the
     heartbeat provided by the master (i.e. the state of the master) is
     greater than or equal to the state of the slave. In other words,
     it checks that the slave isn't ahead of the master. However, if
     the filename provided by the master heartbeat event is different
     than the filename saved for the slave's state, the check always
     fails. This is broken, because when the master rotates its logs,
     the new binary log file will have a different filename (i.e. an
     incremented index counter suffix). For example, if the master
     rotates its binary logs from master-bin.000002 to
     master-bin.000003, master-bin.000003 is ahead of
     master-bin.000002, but the slave will see a difference between the
     filenames and fail the check.

To fix the first problem, this patch disallows passing a heartbeat
event into queue_old_event (which is the source of the error, as it
tries to parse a heartbeat log event). This function (queue_old_event)
was removed with MDEV-30128, so bypassing it for heartbeat events is
not consequential (and it is already also done for
Format_description_events, which are not supported in old binlog file
versions). Note that backporting all of MDEV-30128 was also considered,
but this is less risky for GA.

To fix the second problem, we simply ignore heartbeat events on the
slave if the filenames don't match. This is because during rotation,
it can appear that the slave is ahead of the master, which breaks the
validity of the check (i.e. the check is to ensure the master is
ahead of the slave).

Additionally note that this patch restores a heartbeat check that was
incorrectly removed in 780db8e252

Reviewed-by: Andrei Elkin <andrei.elkin@mariadb.com>
Signed-off-by: Brandon Nesterenko <brandon.nesterenko@mariadb.com>
2025-08-22 15:04:02 -06:00

75 lines
2.2 KiB
Text

#
# Test ensures that a heartbeat event can be replicated from master to slave
# during a slow rotation. MDEV-29981 reported two bugs where the slave could
# stop in error during a slow rotation because of incorrect checks.
#
# To simulate a slow rotation, this test pauses (via debug_sync) after a rotate
# event has been written and synced to disk, but before the new binary log has
# been created. After the rotate event has been received and processed by the
# slave, the test then waits for the next heartbeat event to be sent to the
# slave. Once the heartbeat has been sent, the rotation is completed, and then
# the test ensures replication is ok by creating transactions and ensuring they
# are able to be replicated by the slave. Note that the heartbeat period is set
# to 2 seconds.
#
#
# References:
# MDEV-29881: Replica stops with "Found invalid event in binary log"
#
--source include/have_debug.inc
--source include/have_debug_sync.inc
--source include/have_innodb.inc
--echo # Binlog format independent
--source include/have_binlog_format_row.inc
--source include/master-slave.inc
--echo #
--echo # Initialize test data
--connection slave
--source include/stop_slave.inc
change master to master_heartbeat_period=2;
--source include/start_slave.inc
--echo # Rotating master logs and pausing after Rotate_event is written..
--connection master
set @old_dbug= @@global.debug_dbug;
set @@global.debug_dbug= "+d,stop_after_rotate_written";
--send flush binary logs
--echo # Waiting for Rotate event to write/sync to disk
--connection server_1
set debug_sync="now wait_for rotate_written";
--echo # Sleep 3s so the master sends a heartbeat event to the slave
--sleep 3
--connection server_1
set debug_sync="now signal finish_rotate";
--connection master
--reap
set @@global.debug_dbug= @old_dbug;
--echo #
--echo # Ensure replication continues without error..
--connection master
create table t1 (a int);
insert into t1 values (1);
--sync_slave_with_master
--let $diff_tables=master:test.t1,slave:test.t1
--source include/diff_tables.inc
--echo #
--echo # Cleanup
--connection master
drop table t1;
--source include/save_master_gtid.inc
--connection slave
--source include/sync_with_master_gtid.inc
--source include/rpl_end.inc
--echo # End of rpl_heartbeat_at_rotate.test