maria-developers team mailing list archive

[sujatha <sujatha.sivakumar@xxxxxxxxxxx>]

revision-id: 0038c24f2d388b9b0f3bff9219a53c8900153d02 (mariadb-10.5.4-539-g0038c24f2d3)
parent(s): 190a8312f598fc4892331225104297f6288f23ac
author: Sujatha
committer: Sujatha
timestamp: 2021-03-18 18:41:30 +0530
message:

MDEV-16146: MariaDB slave stops with following errors.

Problem:
========
180511 11:07:58 [ERROR] Slave I/O: Unexpected master's heartbeat data:
heartbeat is not compatible with local info;the event's data: log_file_name
mysql-bin.000009 log_pos 1054262041, Error_code: 1623

Analysis:
=========
In replication setup when master server doesn't have any events to send to
slave server it sends an 'Heartbeat_log_event'. This event carries the
current binary log filename and offset details. The offset values is stored
within 4 bytes of event header. When the size of binary log is higher
than UINT32_MAX the log_pos values will not fit in 4 bytes memory.  It
overflows and hence slave stops with an error.

Fix:
===
Since we cannot extend the fixed header of Log_event class an additional
header named 'extra_header' is introduced. 'extra_header' contains

HB_FLAGS               - 2 bytes
HB_LONG_LOG_POS_OFFSET - 8 bytes

This 'extra_header' is added only in a case where log_pos > UINT32_MAX and
'HB_LONG_LOG_POS_OFFSET_F' will be enabled. On slave while reading the
'Heartbeat_log_event' if 'HB_LONG_LOG_POS_OFFSET_F' is found to be set then
value of 'log_pos' is extracted from 'extra_header'.

---
 .../suite/rpl/r/rpl_incompatible_heartbeat.result  | 20 +++++++++
 .../suite/rpl/t/rpl_incompatible_heartbeat.test    | 47 ++++++++++++++++++++++
 sql/log_event.h                                    | 19 ++++++++-
 sql/log_event_server.cc                            |  8 +++-
 sql/slave.cc                                       | 14 +++++++
 sql/sql_repl.cc                                    | 26 ++++++++++--
 6 files changed, 128 insertions(+), 6 deletions(-)

diff --git a/mysql-test/suite/rpl/r/rpl_incompatible_heartbeat.result b/mysql-test/suite/rpl/r/rpl_incompatible_heartbeat.result
new file mode 100644
index 00000000000..fe2b0436f2d
--- /dev/null
+++ b/mysql-test/suite/rpl/r/rpl_incompatible_heartbeat.result
@@ -0,0 +1,20 @@
+include/master-slave.inc
+[connection master]
+connection master;
+SET @saved_dbug = @@GLOBAL.debug_dbug;
+SET @@global.debug_dbug= '+d,simulate_pos_4G';
+connection slave;
+include/stop_slave.inc
+SET @saved_dbug = @@GLOBAL.debug_dbug;
+SET @@global.debug_dbug= '+d,simulate_pos_4G';
+CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD=0.001;
+include/start_slave.inc
+connection master;
+SET @@GLOBAL.debug_dbug = @saved_dbug;
+connection slave;
+SET @@GLOBAL.debug_dbug = @saved_dbug;
+connection master;
+CREATE TABLE t (f INT) ENGINE=INNODB;
+INSERT INTO t VALUES (10);
+DROP TABLE t;
+include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/t/rpl_incompatible_heartbeat.test b/mysql-test/suite/rpl/t/rpl_incompatible_heartbeat.test
new file mode 100644
index 00000000000..b1aa5435ff4
--- /dev/null
+++ b/mysql-test/suite/rpl/t/rpl_incompatible_heartbeat.test
@@ -0,0 +1,47 @@
+# ==== Purpose ====
+#
+# Test verifies that slave IO thread can process heartbeat events with log_pos
+# values higher than UINT32_MAX.
+#
+# ==== Implementation ====
+#
+# Steps:
+#    0 - Stop slave threads. Configure a small master_heartbeat_period.
+#    1 - Using debug points, simulate a huge binlog offset higher than
+#        UINT32_MAX on master.
+#    2 - Start the slave and observe that slave IO thread is able to process
+#        the offset received through heartbeat event.
+#
+# ==== References ====
+#
+# MDEV-16146: MariaDB slave stops with incompatible heartbeat
+#
+--source include/have_debug.inc
+--source include/have_innodb.inc
+--source include/have_binlog_format_mixed.inc
+# Test simulates binarylog offsets higher than UINT32_MAX
+--source include/have_64bit.inc
+--source include/master-slave.inc
+
+--connection master
+SET @saved_dbug = @@GLOBAL.debug_dbug;
+SET @@global.debug_dbug= '+d,simulate_pos_4G';
+
+--connection slave
+--source include/stop_slave.inc
+SET @saved_dbug = @@GLOBAL.debug_dbug;
+SET @@global.debug_dbug= '+d,simulate_pos_4G';
+CHANGE MASTER TO MASTER_HEARTBEAT_PERIOD=0.001;
+--source include/start_slave.inc
+
+--connection master
+sleep 1;
+SET @@GLOBAL.debug_dbug = @saved_dbug;
+--sync_slave_with_master
+SET @@GLOBAL.debug_dbug = @saved_dbug;
+
+--connection master
+CREATE TABLE t (f INT) ENGINE=INNODB;
+INSERT INTO t VALUES (10);
+DROP TABLE t;
+--source include/rpl_end.inc
diff --git a/sql/log_event.h b/sql/log_event.h
index 4e193232f4b..72d8766cea5 100644
--- a/sql/log_event.h
+++ b/sql/log_event.h
@@ -576,6 +576,22 @@ class String;
 #define MARIA_SLAVE_CAPABILITY_MINE MARIA_SLAVE_CAPABILITY_GTID
 
 
+#define HB_EXTRA_HEADER_LEN 10
+/*
+  Extra header contains flags specific to Heartbeat_log_event and
+  respective data. The length needs to be updated when new memebers are
+  added to this header
+*/
+#define HB_FLAGS_OFFSET 0
+/*
+  When the size of 'log_pos' within Heartbeat_log_event exceeds UINT_MAX32 it
+  cannot be stored in standard header as 'log_pos' is of 4 bytes size. Hence
+  extra_header is introduced. First 2 bytes represent flags. In case of long
+  'log_pos' value 'HB_LONG_LOG_POS_OFFSET_F' bit within the flag will be set.
+  The log_pos is stored witin 'long_log_pos' variables.
+*/
+#define HB_LONG_LOG_POS_OFFSET_F       0x1
+#define HB_LONG_LOG_POS_OFFSET 2
 /**
   @enum Log_event_type
 
@@ -5718,7 +5734,8 @@ bool copy_cache_to_file_wrapped(IO_CACHE *body,
 class Heartbeat_log_event: public Log_event
 {
 public:
-  Heartbeat_log_event(const char* buf, uint event_len,
+  uint16 hb_flags;
+  Heartbeat_log_event(const char* buf, ulong event_len,
                       const Format_description_log_event* description_event);
   Log_event_type get_type_code() { return HEARTBEAT_LOG_EVENT; }
   bool is_valid() const
diff --git a/sql/log_event_server.cc b/sql/log_event_server.cc
index 6dee9b9adf6..2701f4f2f9a 100644
--- a/sql/log_event_server.cc
+++ b/sql/log_event_server.cc
@@ -8493,14 +8493,18 @@ void Ignorable_log_event::pack_info(Protocol *protocol)
 
 
 #if defined(HAVE_REPLICATION)
-Heartbeat_log_event::Heartbeat_log_event(const char* buf, uint event_len,
+Heartbeat_log_event::Heartbeat_log_event(const char* buf, ulong event_len,
                     const Format_description_log_event* description_event)
   :Log_event(buf, description_event)
 {
+  uint16 hb_flags;
   uint8 header_size= description_event->common_header_len;
-  ident_len = event_len - header_size;
+  ident_len = event_len - (header_size + HB_EXTRA_HEADER_LEN);
   set_if_smaller(ident_len,FN_REFLEN-1);
   log_ident= buf + header_size;
+  hb_flags= uint2korr(buf + header_size + ident_len);
+  if (hb_flags & HB_LONG_LOG_POS_OFFSET_F)
+    log_pos= uint8korr(buf + header_size + ident_len + HB_LONG_LOG_POS_OFFSET);
 }
 #endif
 
diff --git a/sql/slave.cc b/sql/slave.cc
index 1da030084ef..f365a1e7b5c 100644
--- a/sql/slave.cc
+++ b/sql/slave.cc
@@ -6493,6 +6493,12 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len)
 
        TODO: handling `when' for SHOW SLAVE STATUS' snds behind
     */
+    DBUG_EXECUTE_IF("simulate_pos_4G",
+    {
+       inc_pos= mi->master_log_pos; // temp_save
+       mi->master_log_pos= ((ulong)2394967295);
+    };);
+
     if (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 */
@@ -6504,6 +6510,14 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len)
       error_msg.append_ulonglong(hb.log_pos);
       goto err;
     }
+    DBUG_EXECUTE_IF("simulate_pos_4G",
+    {
+      if (hb.log_pos > UINT32_MAX)
+      {
+        mi->master_log_pos= inc_pos; // restore
+        DBUG_SET("-d, simulate_pos_4G");
+      }
+    };);
 
     /*
       Heartbeat events doesn't count in the binlog size, so we don't have to
diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc
index 010ea794254..d68ae05b60e 100644
--- a/sql/sql_repl.cc
+++ b/sql/sql_repl.cc
@@ -824,12 +824,14 @@ get_slave_until_gtid(THD *thd, String *out_str)
 */
 static int send_heartbeat_event(binlog_send_info *info,
                                 NET* net, String* packet,
-                                const struct event_coordinates *coord,
+                                struct event_coordinates *coord,
                                 enum enum_binlog_checksum_alg checksum_alg_arg)
 {
   DBUG_ENTER("send_heartbeat_event");
 
   ulong ev_offset;
+  char extra_buf[HB_EXTRA_HEADER_LEN];
+  uint16 hb_flags= 0;
   if (reset_transmit_packet(info, info->flags, &ev_offset, &info->errmsg))
     DBUG_RETURN(1);
 
@@ -850,19 +852,30 @@ static int send_heartbeat_event(binlog_send_info *info,
   size_t event_len = ident_len + LOG_EVENT_HEADER_LEN +
     (do_checksum ? BINLOG_CHECKSUM_LEN : 0);
   int4store(header + SERVER_ID_OFFSET, global_system_variables.server_id);
+  if (coord->pos <= UINT32_MAX)
+  {
+    int4store(header + LOG_POS_OFFSET, coord->pos);  // log_pos
+  }
+  else
+  {
+    hb_flags|= HB_LONG_LOG_POS_OFFSET_F;
+    int2store(extra_buf + HB_FLAGS_OFFSET, hb_flags);
+    int8store(extra_buf + HB_LONG_LOG_POS_OFFSET, coord->pos);
+    event_len+= HB_EXTRA_HEADER_LEN;
+  }
   int4store(header + EVENT_LEN_OFFSET, event_len);
   int2store(header + FLAGS_OFFSET, 0);
 
-  int4store(header + LOG_POS_OFFSET, coord->pos);  // log_pos
-
   packet->append(header, sizeof(header));
   packet->append(p, ident_len);             // log_file_name
+  packet->append(extra_buf, sizeof(extra_buf));
 
   if (do_checksum)
   {
     char b[BINLOG_CHECKSUM_LEN];
     ha_checksum crc= my_checksum(0, (uchar*) header, sizeof(header));
     crc= my_checksum(crc, (uchar*) p, ident_len);
+    crc= my_checksum(crc, (uchar*) extra_buf, sizeof(extra_buf));
     int4store(b, crc);
     packet->append(b, sizeof(b));
   }
@@ -2525,6 +2538,13 @@ static int wait_new_events(binlog_send_info *info,         /* in */
         }
 #endif
         mysql_bin_log.unlock_binlog_end_pos();
+
+	DBUG_EXECUTE_IF("simulate_pos_4G",
+	{
+	  coord.pos= ((ulong)5394967295);
+	  DBUG_SET("-d, simulate_pos_4G");
+	};);
+
         ret= send_heartbeat_event(info,
                                   info->net, info->packet, &coord,
                                   info->current_checksum_alg);