MDEV-40643: Corrupt Heartbeat Log Event can Crash Slave

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

@@ -0,0 +1,76 @@
+include/master-slave.inc
+[connection master]
+connection slave;
+call mtr.add_suppression("Unexpected master's heartbeat data");
+call mtr.add_suppression("Event from master is shorter than its common header");
+call mtr.add_suppression("Relay log write failure: could not queue event from master");
+#
+# Initialize test data
+#
+connection master;
+create table t1 (a int);
+insert into t1 values (1);
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+include/stop_slave.inc
+CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD= 0.5;
+include/start_slave.inc
+connection master;
+set @saved_dbug= @@global.debug_dbug;
+#
+# Test Case 1: a heartbeat that leaves no room for a file name
+#
+connection master;
+set @@global.debug_dbug= "+d,binlog_sender_truncated_heartbeat";
+connection slave;
+include/stop_slave.inc
+include/start_slave.inc
+# Waiting for the IO thread to reject the truncated heartbeat
+include/wait_for_slave_io_error.inc [errno=1595]
+Last_IO_Error = 'Relay log write failure: could not queue event from master'
+# Ensure heartbeat validation rejected the event
+include/assert_grep.inc [The IO thread reported an inconsistent heartbeat event]
+include/assert_grep.inc [The heartbeat error should report an empty log_file_name]
+connection master;
+set @@global.debug_dbug= @saved_dbug;
+connection slave;
+include/stop_slave_sql.inc
+include/start_slave.inc
+#
+# Test Case 2: a heartbeat shorter than the common header
+#
+connection master;
+set @@global.debug_dbug= "+d,binlog_sender_undersized_heartbeat";
+connection slave;
+include/stop_slave.inc
+include/start_slave.inc
+# Waiting for the IO thread to reject the undersized heartbeat
+include/wait_for_slave_io_error.inc [errno=1595]
+Last_IO_Error = 'Relay log write failure: could not queue event from master'
+# Ensure the event was rejected before its header was read
+include/assert_grep.inc [The IO thread reported an event shorter than the common header]
+connection master;
+set @@global.debug_dbug= @saved_dbug;
+connection slave;
+include/stop_slave_sql.inc
+include/start_slave.inc
+#
+# Ensure replication works after the invalid heartbeat events
+#
+connection master;
+insert into t1 values (2);
+include/save_master_gtid.inc
+connection slave;
+include/sync_with_master_gtid.inc
+include/diff_tables.inc [master:t1,slave: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_log_event_underflow.test

mysql-test/suite/rpl/t/rpl_heartbeat_log_event_underflow-master.opt

@@ -0,0 +1 @@
+--binlog-checksum=CRC32

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

@@ -0,0 +1,147 @@
+#
+#   This test verifies that a replica rejects a heartbeat event that is
+# too short to carry the log file name it must hold. Two lengths are
+# covered. An event that reaches the heartbeat parser but leaves no room
+# for a file name must stop the IO thread with an error reporting an
+# empty file name. An event shorter than the common header must be
+# rejected before any parser reads that header. Replication must be able
+# to resume after each.
+#
+#   The debug injections send heartbeats of 17 and 13 bytes. MDEV-40643
+# reported that the 17-byte case underflowed the replica's computed name
+# length and crashed the replica.
+#
+#   Note rpl_heartbeat_log_event_underflow-master.opt sets
+# binlog_checksum=CRC32 on the master for Test Case 1. That is, those four
+# checksum bytes carry the 17-byte heartbeat over queue_event()'s 19-byte
+# minimum length.
+#
+# References:
+#   * MDEV-40643: Corrupt Heartbeat Log Event can Crash Slave
+#   * Bug#39377010: Improve malformed heartbeat handling
+#
+
+--source include/have_debug.inc
+# Test is format independent
+--source include/have_binlog_format_row.inc
+--source include/master-slave.inc
+
+--connection slave
+call mtr.add_suppression("Unexpected master's heartbeat data");
+call mtr.add_suppression("Event from master is shorter than its common header");
+call mtr.add_suppression("Relay log write failure: could not queue event from master");
+
+--echo #
+--echo # Initialize test data
+--echo #
+--connection master
+create table t1 (a int);
+insert into t1 values (1);
+--source include/save_master_gtid.inc
+
+--connection slave
+--source include/sync_with_master_gtid.inc
+
+# Both cases need a heartbeat to arrive promptly. The default period is
+# slave_net_timeout/2. The CHANGE MASTER that rpl_end.inc runs on every
+# server restores it.
+--source include/stop_slave.inc
+CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD= 2;
+--source include/start_slave.inc
+
+--connection master
+set @saved_dbug= @@global.debug_dbug;
+
+--echo #
+--echo # Test Case 1: a heartbeat that leaves no room for a file name
+--echo #
+
+# The dump thread reads the injection when the replica reconnects below.
+--connection master
+set @@global.debug_dbug= "+d,binlog_sender_truncated_heartbeat";
+
+--connection slave
+--source include/stop_slave.inc
+--source include/start_slave.inc
+
+--echo # Waiting for the IO thread to reject the truncated heartbeat
+# queue_event() reports 1623, then handle_slave_io() overwrites it with 1595
+--let $slave_io_errno= 1595
+--let $show_slave_io_error= 1
+--source include/wait_for_slave_io_error.inc
+
+--echo # Ensure heartbeat validation rejected the event
+--let $assert_text= The IO thread reported an inconsistent heartbeat event
+--let $assert_file= $MYSQLTEST_VARDIR/log/mysqld.2.err
+--let $assert_select= Unexpected master.s heartbeat data: inconsistent heartbeat event content
+--let $assert_count= 1
+--source include/assert_grep.inc
+
+# An empty log_file_name shows ident_len was bounded. Reaching this assertion
+# at all is the other half of the evidence.
+--let $assert_text= The heartbeat error should report an empty log_file_name
+--let $assert_file= $MYSQLTEST_VARDIR/log/mysqld.2.err
+--let $assert_select= heartbeat event content;the event.s data: log_file_name  log_pos [0-9]+
+--let $assert_count= 1
+--source include/assert_grep.inc
+
+--connection master
+set @@global.debug_dbug= @saved_dbug;
+
+--connection slave
+--source include/stop_slave_sql.inc
+--source include/start_slave.inc
+
+--echo #
+--echo # Test Case 2: a heartbeat shorter than the common header
+--echo #
+--connection master
+set @@global.debug_dbug= "+d,binlog_sender_undersized_heartbeat";
+
+--connection slave
+--source include/stop_slave.inc
+--source include/start_slave.inc
+
+--echo # Waiting for the IO thread to reject the undersized heartbeat
+--let $slave_io_errno= 1595
+--let $show_slave_io_error= 1
+--source include/wait_for_slave_io_error.inc
+
+--echo # Ensure the event was rejected before its header was read
+--let $assert_text= The IO thread reported an event shorter than the common header
+--let $assert_file= $MYSQLTEST_VARDIR/log/mysqld.2.err
+--let $assert_select= Event from master is shorter than its common header; the event.s length: [0-9]+
+--let $assert_count= 1
+--source include/assert_grep.inc
+
+--connection master
+set @@global.debug_dbug= @saved_dbug;
+
+--connection slave
+--source include/stop_slave_sql.inc
+--source include/start_slave.inc
+
+--echo #
+--echo # Ensure replication works after the invalid heartbeat events
+--echo #
+--connection master
+insert into t1 values (2);
+--source include/save_master_gtid.inc
+
+--connection slave
+--source include/sync_with_master_gtid.inc
+--let $diff_tables=master:t1,slave:t1
+--source include/diff_tables.inc
+
+--echo #
+--echo # Cleanup
+--echo #
+--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_log_event_underflow.test

sql/log_event_server.cc

@@ -8818,20 +8818,34 @@ void Ignorable_log_event::pack_info(Protocol *protocol)
 #if defined(HAVE_REPLICATION)
 Heartbeat_log_event::Heartbeat_log_event(const uchar *buf, uint event_len,
                     const Format_description_log_event* description_event)
-  :Log_event(buf, description_event)
+  :Log_event(buf, description_event), ident_len(0), log_ident(NULL)
 {
-  uint8 header_size= description_event->common_header_len;
+  uint sub_header_len= (log_pos == 0) ? HB_SUB_HEADER_LEN : 0;
+  uint all_headers_len= description_event->common_header_len + sub_header_len;
+
+  /*
+    The comparison is <= rather than <, so an event whose length stops exactly
+    at the headers is rejected along with a shorter one.
+
+      * A shorter event must be rejected out of necessity. ident_len is
+        unsigned, so the subtraction below would wrap and the caller would
+        read the log file name from far past the event.
+      * An event of exactly the header length must be rejected as policy. It
+        carries no log file name, and a heartbeat that names no binary log
+        file tells the replica nothing it can compare its own coordinates
+        against.
+
+    Leaving log_ident at NULL is what reports both to the caller, through
+    is_valid().
+  */
+  if (event_len <= all_headers_len)
+    return;
+
   if (log_pos == 0)
-  {
-    log_pos= uint8korr(buf + header_size);
-    log_ident= buf + header_size + HB_SUB_HEADER_LEN;
-    ident_len= event_len - (header_size + HB_SUB_HEADER_LEN);
-  }
-  else
-  {
-    log_ident= buf + header_size;
-    ident_len = event_len - header_size;
-  }
+    log_pos= uint8korr(buf + description_event->common_header_len);
+
+  log_ident= buf + all_headers_len;
+  ident_len= event_len - all_headers_len;
 }
 #endif
 

sql/slave.cc

@@ -6509,11 +6509,34 @@ static int queue_event(Master_info* mi, const uchar *buf, ulong event_len)
   const uchar *save_buf= NULL; // needed for checksumming the fake Rotate event
   uchar rot_buf[LOG_EVENT_HEADER_LEN + ROTATE_HEADER_LEN + FN_REFLEN];
 
+  /* The shortest event a master of this binlog version can legally send. */
+  ulong min_event_len=
+    mi->rli.relay_log.description_event_for_queue->binlog_version < 4 ?
+    OLD_HEADER_LEN : LOG_EVENT_MINIMAL_HEADER_LEN;
+
   DBUG_ASSERT(checksum_alg == BINLOG_CHECKSUM_ALG_OFF || 
               checksum_alg == BINLOG_CHECKSUM_ALG_UNDEF || 
               checksum_alg == BINLOG_CHECKSUM_ALG_CRC32); 
 
   DBUG_ENTER("queue_event");
+
+  /*
+    Reject an event that is shorter than the common header before anything
+    reads that header. The code below indexes into the header unconditionally,
+    and several of the per-type parsers derive a body length by subtracting
+    the header length, which wraps on a shorter event.
+    event_checksum_test() subtracts BINLOG_CHECKSUM_LEN in the same way.
+  */
+  if (unlikely(event_len < min_event_len))
+  {
+    error= ER_SLAVE_FATAL_ERROR;
+    error_msg.append(STRING_WITH_LEN("Event from master is shorter than its "
+                                     "common header; the event's length: "));
+    error_msg.append_ulonglong(event_len);
+    unlock_data_lock= FALSE;
+    goto err;
+  }
+
   /*
     FD_queue checksum alg description does not apply in a case of
     FD itself. The one carries both parts of the checksum data.

sql/sql_repl.cc

@@ -863,18 +863,36 @@ static int send_heartbeat_event(binlog_send_info *info,
     event_len+= HB_SUB_HEADER_LEN;
   }
 
+  size_t hb_header_len= sizeof(header);
+#ifndef DBUG_OFF
+  /*
+    Corrupt the heartbeat event to test that a replica can correctly identify
+    malformed events. 17 bytes keeps LOG_POS_OFFSET on the wire and clears
+    queue_event()'s minimum length, so the heartbeat parser rejects it.
+    13 bytes falls under that minimum, so queue_event() rejects it first.
+  */
+  DBUG_EXECUTE_IF("binlog_sender_truncated_heartbeat", hb_header_len= 17;);
+  DBUG_EXECUTE_IF("binlog_sender_undersized_heartbeat", hb_header_len= 13;);
+  if (hb_header_len != sizeof(header))
+  {
+    ident_len= 0;
+    event_len= hb_header_len + (sub_header_in_use ? HB_SUB_HEADER_LEN : 0) +
+      (do_checksum ? BINLOG_CHECKSUM_LEN : 0);
+  }
+#endif
+
   int4store(header + EVENT_LEN_OFFSET, event_len);
   int2store(header + FLAGS_OFFSET, 0);
 
-  packet->append(header, sizeof(header));
+  packet->append(header, hb_header_len);
   if (sub_header_in_use)
     packet->append(sub_header_buf, sizeof(sub_header_buf));
   packet->append(p, ident_len);                    // log_file_name
 
   if (do_checksum)
   {
     char b[BINLOG_CHECKSUM_LEN];
-    ha_checksum crc= my_checksum(0, (uchar*) header, sizeof(header));
+    ha_checksum crc= my_checksum(0, (uchar*) header, hb_header_len);
     if (sub_header_in_use)
       crc= my_checksum(crc, (uchar*) sub_header_buf, sizeof(sub_header_buf));
     crc= my_checksum(crc, (uchar*) p, ident_len);