Bug #18789758 DATA INCONSISTENCIES WHEN MASTER HAS TRUNCATED

Venkatesh Duggirala · Venkatesh Duggirala · commit 6e6add6bb564 · 2014-11-18T09:54:31.000+05:30
BINARY LOG WITH GTID AFTER CRASH
      Problem:
       Master's dump thread is not detecting the case where Slave's
       gtid executed set is having more gtids than Master's gtid
       executed set with respective to Master's UUID.

      Analysis &amp; Fix:
       In normal scenarios, it is not possible that Slave will
       contain more gtids than Master with respective to Master's UUID.
       But it could be possible case if Master's binary log is
       truncated(due to raid failure) or Master's binary log is
       deleted but GTID_PURGED was not set properly. That scenario
       needs to be validated, i.e., it should *always* be the case that
       Slave's gtid executed set (+retrieved set) is a subset of
       Master's gtid executed set with respective to Master's UUID.
       If it happens, Master's dump thread will be stopped and this
       situation will be informed to Slave during the handshake (thus.
       slave I/O thread also be stopped with an error
       (ER_MASTER_FATAL_ERROR_READING_BINLOG). Otherwise, it can lead
       to data inconsistency between Master and Slave.
diff --git a/mysql-test/suite/rpl/r/rpl_check_gtid.result b/mysql-test/suite/rpl/r/rpl_check_gtid.result
@@ -229,6 +229,7 @@ FLUSH LOGS;
 include/stop_slave.inc
 RESET SLAVE;
 RESET MASTER;
+RESET MASTER;
 include/start_slave.inc
 BEGIN;
 INSERT INTO t1 VALUES(1);
@@ -246,6 +247,7 @@ FLUSH LOGS;
 include/stop_slave.inc
 RESET SLAVE;
 RESET MASTER;
+RESET MASTER;
 include/start_slave.inc
 BEGIN;
 INSERT INTO t1 VALUES(1);
@@ -263,6 +265,7 @@ FLUSH LOGS;
 include/stop_slave.inc
 RESET SLAVE;
 RESET MASTER;
+RESET MASTER;
 include/start_slave.inc
 BEGIN;
 INSERT INTO t1 VALUES(1);
@@ -280,6 +283,7 @@ FLUSH LOGS;
 include/stop_slave.inc
 RESET SLAVE;
 RESET MASTER;
+RESET MASTER;
 include/start_slave.inc
 BEGIN;
 INSERT INTO t1 VALUES(1);
diff --git a/mysql-test/suite/rpl/r/rpl_gtid_validate_slave_gtids.result b/mysql-test/suite/rpl/r/rpl_gtid_validate_slave_gtids.result
@@ -3,15 +3,26 @@ Warnings:
 Note	####	Sending passwords in plain text without SSL/TLS is extremely insecure.
 Note	####	Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
 [connection master]
-SET GLOBAL GTID_PURGED ="master_uuid:1-2";
+SET GLOBAL GTID_PURGED= "master_uuid:1-2";
 CREATE TABLE t1(i INT);
 DROP TABLE t1;
 START SLAVE IO_THREAD;
 include/wait_for_slave_io_error.inc [errno=1236]
 Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.''
-SET GLOBAL GTID_PURGED ="master_uuid:1-2";
+SET GLOBAL GTID_PURGED= "master_uuid:1-2";
 include/start_slave.inc
 include/sync_slave_sql_with_master.inc
 include/assert.inc [Slave should be able to get GTID-3 and 4 now.]
 call mtr.add_suppression(".*Master has purged binary logs containing GTIDs that the slave requires.*");
+include/rpl_reset.inc
+CREATE TABLE t1(i INT);
+DROP TABLE t1;
+include/stop_slave.inc
+include/rpl_restart_server.inc [server_number=1]
+START SLAVE IO_THREAD;
+include/wait_for_slave_io_error.inc [errno=1236]
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'Slave has more GTIDs than the master has, using the master's SERVER_UUID. This may indicate that the end of the binary log was truncated or that the last binary log file was lost, e.g., after a power or disk failure when sync_binlog != 1. The master may or may not have rolled back transactions that were already replica''
+call mtr.add_suppression(".*Slave has more GTIDs than the master has.*");
+SET GLOBAL GTID_PURGED= "master_uuid:1-2";
+include/start_slave.inc
 include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/r/rpl_kill_query.result b/mysql-test/suite/rpl/r/rpl_kill_query.result
@@ -45,6 +45,7 @@ include/assert.inc [Nothing should be inserted on slave]
 ---- Clean up ----
 include/stop_slave_io.inc
 RESET SLAVE;
+RESET MASTER;
 DROP DATABASE db1;
 [connection master]
 RESET MASTER;
diff --git a/mysql-test/suite/rpl/r/rpl_packet.result b/mysql-test/suite/rpl/r/rpl_packet.result
@@ -50,6 +50,7 @@ Last_IO_Error = 'Got a packet bigger than 'slave_max_allowed_packet' bytes'
 STOP SLAVE;
 RESET SLAVE;
 RESET MASTER;
+RESET MASTER;
 SET @max_allowed_packet_0= @@session.max_allowed_packet;
 SHOW BINLOG EVENTS;
 SET @max_allowed_packet_1= @@session.max_allowed_packet;
diff --git a/mysql-test/suite/rpl/t/rpl_check_gtid.test b/mysql-test/suite/rpl/t/rpl_check_gtid.test
@@ -504,6 +504,7 @@ while ($i != 5)
   --connection slave
   --source include/stop_slave.inc
   RESET SLAVE;
+  RESET MASTER;
   --connection master
   RESET MASTER;
   --connection slave
@@ -525,14 +526,13 @@ while ($i != 5)
 
   #  5.3 - Makes the slave to retrieve and apply these transactions.
   --source include/sync_slave_sql_with_master.inc
-
   # Check property 1.2, 2.1, 3.1 and 3.2
   --let $binlog= binlog
   --let $server_uuid= $master_uuid
-  --let $gtid_set_ini= 1
-  --let $gtid_set_end= 4
-  --let $gtid_ini=
-  --let $gtid_end=
+  --let $gtid_set_ini=
+  --let $gtid_set_end=
+  --let $gtid_ini= 1
+  --let $gtid_end= 2
   --source extra/rpl_tests/rpl_check_gtid.inc
 
   #  5.4 - Rotates both the binary logs on the slave and master.
diff --git a/mysql-test/suite/rpl/t/rpl_gtid_validate_slave_gtids.test b/mysql-test/suite/rpl/t/rpl_gtid_validate_slave_gtids.test
@@ -22,7 +22,7 @@
 # Step-1) Master wants to set 1 and 2 GTIDs in GTID_PURGED
 --let $master_uuid= `SELECT @@GLOBAL.SERVER_UUID`
 --replace_result $master_uuid master_uuid
---eval SET GLOBAL GTID_PURGED ="$master_uuid:1-2"
+--eval SET GLOBAL GTID_PURGED= "$master_uuid:1-2"
 
 # Step-2) Do some dummy transactions
 CREATE TABLE t1(i INT);  # GTID-3
@@ -42,7 +42,7 @@ START SLAVE IO_THREAD;
 
 # Fix the problem by setting GTID_PURGED on Slave as well.
 --replace_result $master_uuid master_uuid
---eval SET GLOBAL GTID_PURGED ="$master_uuid:1-2"
+--eval SET GLOBAL GTID_PURGED= "$master_uuid:1-2"
 
 # Now start slave threads. Slave will ask Master to send all GTIDs
 # except GTID:1-2 which should not be a problem and should not throw
@@ -56,4 +56,73 @@ START SLAVE IO_THREAD;
 --source include/assert.inc
 
 call mtr.add_suppression(".*Master has purged binary logs containing GTIDs that the slave requires.*");
+
+###############################################################################
+#Bug #18789758  DATA INCONSISTENCIES WHEN MASTER HAS TRUNCATED BINARY LOG WITH
+# GTID AFTER CRASH
+# Problem:
+#   Master's dump thread is not detecting the case where Slave's gtid executed
+#   set is having more gtids than Master's gtid executed set with respective
+#   to Master's UUID.
+# Fix:
+#   If it happens, dump thread will be stopped during the handshake
+#   with Slave(thus the Slave's I/O thread will be stopped with the
+#   error). Otherwise, it can lead to data inconsistency
+#   between Master and Slave.
+#
+# Steps to reproduce:
+#  1) Execute some sample gtid transactions on Master
+#  2) Let it reach Slave
+#  3) Fake raid failure( by manually deleting binary log file)
+#  4) Restart Master, thus removing those gtids from executed gtid set.
+#  5) Restart slave's I/O thread, Slave sends its gtids which are purged on
+#      Master
+#  6) Make sure I/O thread gets error and informs the situation to the Slave.
+#  7) Verify that situation is recovered back normal after setting GTID_PURGED
+#      value to those purged gtids.
+###############################################################################
+
+# Cleanup from the next test script
+--connection master
+--source include/rpl_reset.inc
+
+# Step-1) Execute some sample gtid transactions on Master
+CREATE TABLE t1(i INT);
+DROP TABLE t1;
+
+# Step-2) Let it reach Slave.
+--sync_slave_with_master
+--source include/stop_slave.inc
+
+# Step-3) Fake raid failure( by manually deleting binary log file)
+--connection master
+--let $master_datadir= `SELECT @@datadir;`
+--remove_file $master_datadir/master-bin.000001
+--remove_file $master_datadir/master-bin.index
+
+# Step-4) Restart Master, thus removing those gtids from executed gtid set.
+--let $rpl_server_number= 1
+--source include/rpl_restart_server.inc
+
+# Step-5) Restart slave's I/O thread, Slave sends its gtids which are purged on Master
+--connection slave
+START SLAVE IO_THREAD;
+
+# Step-6) Make sure I/O thread gets error and informs the situation to the Slave.
+--let $slave_io_errno= convert_error(ER_MASTER_FATAL_ERROR_READING_BINLOG)
+--let $show_slave_io_error= 1
+--source include/wait_for_slave_io_error.inc
+call mtr.add_suppression(".*Slave has more GTIDs than the master has.*");
+
+# Step-7) Verify that situation is recovered back normal after setting GTID_PURGED
+#          value to those purged gtids.
+--connection master
+--let $master_uuid= `SELECT @@GLOBAL.SERVER_UUID`
+--replace_result $master_uuid master_uuid
+--eval SET GLOBAL GTID_PURGED= "$master_uuid:1-2"
+
+--connection slave
+--source include/start_slave.inc
+
+# Cleanup
 --source include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/t/rpl_kill_query.test b/mysql-test/suite/rpl/t/rpl_kill_query.test
@@ -63,6 +63,7 @@ CALL mtr.add_suppression("The slave coordinator and worker threads are stopped,
 --echo ---- Clean up ----
 --source include/stop_slave_io.inc
 RESET SLAVE;
+RESET MASTER;
 DROP DATABASE db1;
 --source include/rpl_connection_master.inc
 RESET MASTER;
diff --git a/mysql-test/suite/rpl/t/rpl_packet.test b/mysql-test/suite/rpl/t/rpl_packet.test
@@ -151,6 +151,7 @@ connection slave;
 # Remove the bad binlog and clear error status on slave.
 STOP SLAVE;
 RESET SLAVE;
+RESET MASTER;
 --connection master
 RESET MASTER;
 
diff --git a/sql/rpl_gtid.h b/sql/rpl_gtid.h
@@ -1,4 +1,4 @@
-/* Copyright (c) 2011, 2013, Oracle and/or its affiliates. All rights reserved.
+/* Copyright (c) 2011, 2014, Oracle and/or its affiliates. All rights reserved.
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License as
@@ -1032,6 +1032,24 @@ class Gtid_set
   enum_return_status ensure_sidno(rpl_sidno sidno);
   /// Returns true if this Gtid_set is a subset of the other Gtid_set.
   bool is_subset(const Gtid_set *super) const;
+
+  /**
+    Returns true if this Gtid_set is a subset of the given gtid_set
+    on the given superset_sidno and subset_sidno.
+
+    @param super          Gtid_set with which 'this'::gtid_set needs to be
+                           compared
+    @param superset_sidno The sidno that will be compared, relative to
+                           super->sid_map.
+    @param subset_sidno   The sidno that will be compared, relative to
+                           this->sid_map.
+    @return true          If 'this' Gtid_set is subset of given
+                           'super' Gtid_set.
+            false         If 'this' Gtid_set is *not* subset of given
+                           'super' Gtid_set.
+  */
+  bool is_subset_for_sid(const Gtid_set *super, rpl_sidno superset_sidno,
+                         rpl_sidno subset_sidno) const;
   /// Returns true if there is a least one element of this Gtid_set in
   /// the other Gtid_set.
   bool is_intersection_nonempty(const Gtid_set *other) const;
@@ -2266,6 +2284,11 @@ class Gtid_state
   const Owned_gtids *get_owned_gtids() const { return &owned_gtids; }
   /// Return the server's SID's SIDNO
   rpl_sidno get_server_sidno() const { return server_sidno; }
+  /// Return the server's SID
+  const rpl_sid &get_server_sid() const
+  {
+    return global_sid_map->sidno_to_sid(server_sidno);
+  }
 #ifndef DBUG_OFF
   /**
     Debug only: Returns an upper bound on the length of the string
diff --git a/sql/rpl_gtid_set.cc b/sql/rpl_gtid_set.cc
@@ -1,4 +1,4 @@
-/* Copyright (c) 2011, 2013, Oracle and/or its affiliates. All rights reserved.
+/* Copyright (c) 2011, 2014, Oracle and/or its affiliates. All rights reserved.
 
    This program is free software; you can redistribute it and/or
    modify it under the terms of the GNU General Public License as
@@ -1053,6 +1053,49 @@ bool Gtid_set::is_interval_subset(Const_interval_iterator *sub,
   DBUG_RETURN(true);
 }
 
+bool Gtid_set::is_subset_for_sid(const Gtid_set *super,
+                                 rpl_sidno superset_sidno,
+                                 rpl_sidno subset_sidno) const
+{
+  DBUG_ENTER("Gtid_set::is_subset_for_sidno");
+  /*
+    The following assert code is to see that caller acquired
+    either write or read lock on global_sid_lock.
+    Note that if it is read lock, then it should also
+    acquire lock on sidno.
+    i.e., the caller must acquire lock either A1 way or A2 way.
+        A1. global_sid_lock.wrlock()
+        A2. global_sid_lock.rdlock(); gtid_state.lock_sidno(sidno)
+  */
+  if (sid_lock != NULL)
+    super->sid_lock->assert_some_lock();
+  if (super->sid_lock != NULL)
+    super->sid_lock->assert_some_lock();
+  /*
+    If subset(i.e, this object) does not have required sid in it, i.e.,
+    subset_sidno is zero, then it means it is subset of any given
+    super set. Hence return true.
+  */
+  if (subset_sidno == 0)
+    DBUG_RETURN(true);
+  /*
+    If superset (i.e., the passed gtid_set) does not have given sid in it,
+    i.e., superset_sidno is zero, then it means it cannot be superset
+    to any given subset. Hence return false.
+  */
+  if (superset_sidno == 0)
+    DBUG_RETURN(false);
+  /*
+    Once we have valid(non-zero) subset's and superset's sid numbers, call
+    is_interval_subset().
+  */
+  Const_interval_iterator subset_ivit(this, subset_sidno);
+  Const_interval_iterator superset_ivit(super, superset_sidno);
+  if (!is_interval_subset(&subset_ivit, &superset_ivit))
+    DBUG_RETURN(false);
+
+  DBUG_RETURN(true);
+}
 
 bool Gtid_set::is_subset(const Gtid_set *super) const
 {
diff --git a/sql/rpl_master.cc b/sql/rpl_master.cc
@@ -950,6 +950,34 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
   {
     if (using_gtid_protocol)
     {
+      /*
+        In normal scenarios, it is not possible that Slave will
+        contain more gtids than Master with resepctive to Master's
+        UUID. But it could be possible case if Master's binary log
+        is truncated(due to raid failure) or Master's binary log is
+        deleted but GTID_PURGED was not set properly. That scenario
+        needs to be validated, i.e., it should *always* be the case that
+        Slave's gtid executed set (+retrieved set) is a subset of
+        Master's gtid executed set with respective to Master's UUID.
+        If it happens, dump thread will be stopped during the handshake
+        with Slave (thus the Slave's I/O thread will be stopped with the
+        error. Otherwise, it can lead to data inconsistency between Master
+        and Slave.
+      */
+      Sid_map* slave_sid_map= slave_gtid_executed->get_sid_map();
+      DBUG_ASSERT(slave_sid_map);
+      global_sid_lock->wrlock();
+      const rpl_sid &server_sid= gtid_state->get_server_sid();
+      rpl_sidno subset_sidno= slave_sid_map->sid_to_sidno(server_sid);
+      if (!slave_gtid_executed->is_subset_for_sid(gtid_state->get_logged_gtids(),
+                                                  gtid_state->get_server_sidno(),
+                                                  subset_sidno))
+      {
+        errmsg= ER(ER_SLAVE_HAS_MORE_GTIDS_THAN_MASTER);
+        my_errno= ER_MASTER_FATAL_ERROR_READING_BINLOG;
+        global_sid_lock->unlock();
+        GOTO_ERR;
+      }
       /*
         Setting GTID_PURGED (when GTID_EXECUTED set is empty i.e., when
         previous_gtids are also empty) will make binlog rotate. That
@@ -975,8 +1003,7 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
         while checking for subset previous_gtids binary log, the logic
         will not find one and an error ER_MASTER_HAS_PURGED_REQUIRED_GTIDS
         is thrown from there.
-       */
-      global_sid_lock->wrlock();
+      */
       if (!gtid_state->get_lost_gtids()->is_subset(slave_gtid_executed))
       {
         errmsg= ER(ER_MASTER_HAS_PURGED_REQUIRED_GTIDS);
diff --git a/sql/share/errmsg-utf8.txt b/sql/share/errmsg-utf8.txt
@@ -7106,6 +7106,9 @@ ER_PLUGIN_CANNOT_BE_UNINSTALLED
 
 ER_GTID_UNSAFE_BINLOG_SPLITTABLE_STATEMENT_AND_GTID_GROUP
   eng "Cannot execute statement because it needs to be written to the binary log as multiple statements, and this is not allowed when @@SESSION.GTID_NEXT == 'UUID:NUMBER'."
+
+ER_SLAVE_HAS_MORE_GTIDS_THAN_MASTER
+  eng "Slave has more GTIDs than the master has, using the master's SERVER_UUID. This may indicate that the end of the binary log was truncated or that the last binary log file was lost, e.g., after a power or disk failure when sync_binlog != 1. The master may or may not have rolled back transactions that were already replicated to the slave. Suggest to replicate any transactions that master has rolled back from slave to master, and/or commit empty transactions on master to account for transactions that have been committed on master but are not included in GTID_EXECUTED."
 #
 #  End of 5.6 error messages.
 #
