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 780db8e

Reviewed-by: Andrei Elkin <andrei.elkin@mariadb.com>
Signed-off-by: Brandon Nesterenko <brandon.nesterenko@mariadb.com>

Author: bnestere

mysql-test/suite/rpl/r/rpl_heartbeat_at_rotate.result

@@ -0,0 +1,38 @@
+# Binlog format independent
+include/master-slave.inc
+[connection master]
+#
+# Initialize test data
+connection slave;
+include/stop_slave.inc
+change master to master_heartbeat_period=2;
+include/start_slave.inc
+# 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";
+flush binary logs;
+# Waiting for Rotate event to write/sync to disk
+connection server_1;
+set debug_sync="now wait_for rotate_written";
+# Sleep 3s so the master sends a heartbeat event to the slave
+connection server_1;
+set debug_sync="now signal finish_rotate";
+connection master;
+set @@global.debug_dbug= @old_dbug;
+#
+# Ensure replication continues without error..
+connection master;
+create table t1 (a int);
+insert into t1 values (1);
+connection slave;
+include/diff_tables.inc [master:test.t1,slave:test.t1]
+#
+# Cleanup
+connection master;
+drop table t1;
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+include/rpl_end.inc
+# End of rpl_heartbeat_at_rotate.test

mysql-test/suite/rpl/t/rpl_heartbeat_at_rotate.test

@@ -0,0 +1,75 @@
+#
+# 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

sql/log.cc

@@ -5653,6 +5653,12 @@ int MYSQL_BIN_LOG::new_file_impl()
   }
   update_binlog_end_pos();
 
+  DBUG_EXECUTE_IF("stop_after_rotate_written", {
+    DBUG_ASSERT(!debug_sync_set_action(
+        current_thd,
+        STRING_WITH_LEN("now SIGNAL rotate_written WAIT_FOR finish_rotate")));
+  });
+
   old_name=name;
   name=0;				// Don't free name
   close_flag= LOG_CLOSE_TO_BE_OPENED | LOG_CLOSE_INDEX;

sql/slave.cc

@@ -6508,8 +6508,9 @@ static int queue_event(Master_info* mi, const uchar *buf, ulong event_len)
   }
   DBUG_ASSERT(((uchar) buf[FLAGS_OFFSET] & LOG_EVENT_ACCEPT_OWN_F) == 0);
 
-  if (mi->rli.relay_log.description_event_for_queue->binlog_version<4 &&
-      buf[EVENT_TYPE_OFFSET] != FORMAT_DESCRIPTION_EVENT /* a way to escape */)
+  if (mi->rli.relay_log.description_event_for_queue->binlog_version < 4 &&
+      buf[EVENT_TYPE_OFFSET] != FORMAT_DESCRIPTION_EVENT /* a way to escape */
+      && buf[EVENT_TYPE_OFFSET] != HEARTBEAT_LOG_EVENT)
     DBUG_RETURN(queue_old_event(mi,buf,event_len));
 
 #ifdef ENABLED_DEBUG_SYNC
@@ -6806,17 +6807,31 @@ static int queue_event(Master_info* mi, const uchar *buf, ulong event_len)
        
        Heartbeat is sent only after an event corresponding to the corrdinates
        the heartbeat carries.
-       Slave can not have a higher coordinate except in the only
-       special case when mi->master_log_name, master_log_pos have never
-       been updated by Rotate event i.e when slave does not have any history
-       with the master (and thereafter mi->master_log_pos is NULL).
+
+       Slave can not have a higher coordinate except when rotating logs. That
+       is, either
+         1. when mi->master_log_name, master_log_pos have never been updated by
+            Rotate event i.e when slave does not have any history with the
+            master (and thereafter mi->master_log_pos is NULL)
+         2. if a heartbeat is sent during a slow rotation, the master can send
+            its Rotate event (thereby increasing the mi->master_log_name); yet
+            the sent heartbeat may still be for the old log file.
+
+       Therefore, state comparison is only valid when the log file names match,
+       otherwise the heartbeat is ignored.
 
        Slave can have lower coordinates, if some event from master was omitted.
 
        TODO: handling `when' for SHOW SLAVE STATUS' snds behind
+
+       TODO: Extend heartbeat events to use GTIDs instead of binlog
+         coordinates. This would alleviate the strange exceptions during log
+         rotation.
     */
-    if (memcmp(mi->master_log_name, hb.get_log_ident(), hb.get_ident_len()) ||
-        mi->master_log_pos > hb.log_pos) {
+    if (mi->master_log_pos &&
+        !memcmp(mi->master_log_name, hb.get_log_ident(), hb.get_ident_len()) &&
+        mi->master_log_pos > hb.log_pos)
+    {
       /* missed events of heartbeat from the past */
       error= ER_SLAVE_HEARTBEAT_FAILURE;
       error_msg.append(STRING_WITH_LEN("heartbeat is not compatible with local info;"));