Bug#18731211 Duplicate slave server_uuid in replication

Venkatesh Duggirala · Venkatesh Duggirala · commit 5a9162c0b926 · 2014-07-17T16:56:55.000+05:30
forum gives no specific error message

Problem &amp; Analysis: 
===================
When a new slave joins to a replication forum with uuid which
is exactly same as one of the existing slave's uuid, then master is 
confused between old slave and the newly joined slave. When com_binlog_send
request comes from newly joined slave, it thinks that old slave's dump
thread is zombie and kills it. After some time, old slave tries to reconnect
to the master and sends com_binlog_send request to Master. Then Master
thinks that newly joined slave's dump thread is zombie and kills it.
This ping-pong reconnections between Master-&gt;old_slave and Master-&gt;new_slave
happens continously. This is known expected behaviour but the
error message in old_slave and new_slave's error log file is not clear
enough to identify this situation.

Information in error log file was:
"received end packet from server, apparent master shutdown" which
does not say anything about server_uuid misconfiguration in the
replication forum.

Fix: Changing the error message which clearly mentions all the possible
causes which resulted this disconnection.

New information in error log file is: 
"Slave: received end packet from server due to dump thread being killed on master.
Dump threads are killed for example during master shutdown,
explicitly by a user, or when the master receives a binlog send
request from a duplicate server UUID &lt;server_uuid&gt;. "

And also a NOTE is added on master's error log file with the following
information when log_warnings is greater than 1.
"While initializing dump thread for slave with UUID &lt;slave_uuid&gt;,
found a zombie dump thread with the same UUID.
Master is killing the zombie dump thread."
diff --git a/mysql-test/suite/rpl/r/rpl_server_uuid.result b/mysql-test/suite/rpl/r/rpl_server_uuid.result
@@ -6,7 +6,7 @@ Note	####	Storing MySQL user name or password information in the master info rep
 call mtr.add_suppression("Slave I/O thread .* register on master");
 call mtr.add_suppression("Slave I/O: Master command COM_REGISTER_SLAVE failed: .*");
 CALL mtr.add_suppression(".*master and slave have equal MySQL server UUIDs.*");
-CALL mtr.add_suppression("Master's UUID has changed, its old UUID is.*");
+CALL mtr.add_suppression("Master's UUID has changed, although this should not happen unless you have changed it manually");
 CALL mtr.add_suppression("Slave I/O: SET @master_heartbeat_period to master failed with error: Lost connection to MySQL server during query");
 CALL mtr.add_suppression("Notifying master by SET @master_binlog_checksum= @@global.binlog_checksum failed with error");
 include/sync_slave_sql_with_master.inc
@@ -117,4 +117,25 @@ include/check_slave_param.inc [Slave_IO_Running]
 CHANGE MASTER TO 
 MASTER_LOG_FILE= 'MASTER_LOG_FILE', MASTER_LOG_POS= MASTER_POS;
 include/start_slave.inc
+
+# Case 6:
+# In an existing master-slave replication forum (M->S1), if another
+# slave (S2) with the same UUID as S1 joins the forum and connects
+# to Master(M), then there will be ping-pong reconnections happens
+# between M->S2, M->S1, M->S2, M->S1,.... And both slave1 and slave2
+# will be informed about this UUID misconfiguration in their error
+# log file. And Master log will be populated with information that
+# it found a zombie dump thread and it is killing it(only when
+# log_warnings is greater than 1)
+-----------------------------------------------------------------------------
+include/rpl_restart_server.inc [server_number=3]
+CREATE TABLE t1(i int);
+DROP TABLE t1;
+include/sync_slave_sql_with_master.inc
+include/sync_slave_sql_with_master.inc
+Pattern "found a zombie dump thread with the same UUID" found
+Pattern "master receives a binlog send request from a duplicate server UUID" found
+Pattern "master receives a binlog send request from a duplicate server UUID" found
+include/rpl_restart_server.inc [server_number=3]
+include/stop_slave.inc
 include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/t/rpl_server_uuid.cnf b/mysql-test/suite/rpl/t/rpl_server_uuid.cnf
@@ -1,8 +1,16 @@
 !include ../my.cnf
 
+[mysqld.1]
+log-warnings=2
+log-error=../../tmp/rpl_server_uuid_test.mysqld.1.err
+
+[mysqld.2]
+log-error=../../tmp/rpl_server_uuid_test.mysqld.2.err
+
 [mysqld.3]
 replicate-same-server-id=1
 gtid-mode=off
+log-error=../../tmp/rpl_server_uuid_test.mysqld.3.err
 
 [ENV]
 SERVER_MYPORT_3=		@mysqld.3.port
diff --git a/mysql-test/suite/rpl/t/rpl_server_uuid.test b/mysql-test/suite/rpl/t/rpl_server_uuid.test
@@ -18,7 +18,7 @@
 call mtr.add_suppression("Slave I/O thread .* register on master");
 call mtr.add_suppression("Slave I/O: Master command COM_REGISTER_SLAVE failed: .*");
 CALL mtr.add_suppression(".*master and slave have equal MySQL server UUIDs.*");
-CALL mtr.add_suppression("Master's UUID has changed, its old UUID is.*");
+CALL mtr.add_suppression("Master's UUID has changed, although this should not happen unless you have changed it manually");
 CALL mtr.add_suppression("Slave I/O: SET @master_heartbeat_period to master failed with error: Lost connection to MySQL server during query");
 CALL mtr.add_suppression("Notifying master by SET @master_binlog_checksum= @@global.binlog_checksum failed with error");
 
@@ -236,4 +236,66 @@ RESET SLAVE;
 eval CHANGE MASTER TO 
        MASTER_LOG_FILE= '$old_master_log_file', MASTER_LOG_POS= $old_master_log_pos;
 --source include/start_slave.inc
+
+--echo
+--echo # Case 6:
+--echo # In an existing master-slave replication forum (M->S1), if another
+--echo # slave (S2) with the same UUID as S1 joins the forum and connects
+--echo # to Master(M), then there will be ping-pong reconnections happens
+--echo # between M->S2, M->S1, M->S2, M->S1,.... And both slave1 and slave2
+--echo # will be informed about this UUID misconfiguration in their error
+--echo # log file. And Master log will be populated with information that
+--echo # it found a zombie dump thread and it is killing it(only when
+--echo # log_warnings is greater than 1)
+--echo -----------------------------------------------------------------------------
+
+# Step-1: Copy server 2(S1)'s auto.cnf into server 3 (S2)'s data directory.
+--connection server_2
+--let $datadir2=`select @@datadir`
+-- connection server_3
+--let $datadir3=`select @@datadir`
+--copy_file $datadir3/auto.cnf $datadir3/auto_backup.cnf
+--remove_file $datadir3/auto.cnf
+--copy_file $datadir2/auto.cnf $datadir3/auto.cnf
+
+# Step-2: Restart the server(two servers with the same UUID)
+--let $rpl_server_number= 3
+--source include/rpl_restart_server.inc
+
+# Step-3: Just do some command on server_1
+--connection server_1
+CREATE TABLE t1(i int);
+DROP TABLE t1;
+
+# Step-4: Sync the data on both the slaves and observe that
+# sync will be success at both slaves.
+--let $sync_slave_connection= server_2
+--source include/sync_slave_sql_with_master.inc
+
+--connection server_1
+--let $sync_slave_connection= server_3
+--source include/sync_slave_sql_with_master.inc
+
+# Step-5: Observe that misconfiguration messages are in their respective
+# error log files.
+
+--let SEARCH_FILE=$MYSQLTEST_VARDIR/tmp/rpl_server_uuid_test.mysqld.1.err
+--let SEARCH_PATTERN=found a zombie dump thread with the same UUID
+--source include/search_pattern.inc
+
+--let SEARCH_FILE=$MYSQLTEST_VARDIR/tmp/rpl_server_uuid_test.mysqld.2.err
+--let SEARCH_PATTERN=master receives a binlog send request from a duplicate server UUID
+--source include/search_pattern.inc
+
+--let SEARCH_FILE=$MYSQLTEST_VARDIR/tmp/rpl_server_uuid_test.mysqld.3.err
+--let SEARCH_PATTERN=master receives a binlog send request from a duplicate server UUID
+--source include/search_pattern.inc
+
+# Cleanup (restore the server 3's auto.cnf back to proper one and restart)
+--remove_file $datadir3/auto.cnf
+--copy_file $datadir3/auto_backup.cnf $datadir3/auto.cnf
+--remove_file $datadir3/auto_backup.cnf
+--let $rpl_server_number= 3
+--source include/rpl_restart_server.inc
+--source include/stop_slave.inc
 --source include/rpl_end.inc
diff --git a/scripts/mysqlaccess.conf b/scripts/mysqlaccess.conf
diff --git a/sql/rpl_master.cc b/sql/rpl_master.cc
@@ -1951,6 +1951,11 @@ void kill_zombie_dump_threads(String *slave_uuid)
       it will be slow because it will iterate through the list
       again. We just to do kill the thread ourselves.
     */
+    if (log_warnings > 1)
+      sql_print_information("While initializing dump thread for slave with "
+                            "UUID <%s>, found a zombie dump thread with "
+                            "the same UUID. Master is killing the zombie dump "
+                            "thread.", slave_uuid->c_ptr());
     tmp->awake(THD::KILL_QUERY);
     mysql_mutex_unlock(&tmp->LOCK_thd_data);
   }
diff --git a/sql/rpl_slave.cc b/sql/rpl_slave.cc
@@ -3275,9 +3275,13 @@ static ulong read_event(MYSQL* mysql, Master_info *mi, bool* suppress_warnings)
   /* Check if eof packet */
   if (len < 8 && mysql->net.read_pos[0] == 254)
   {
-    sql_print_information("Slave: received end packet from server, apparent "
-                          "master shutdown: %s",
-                     mysql_error(mysql));
+     sql_print_information("Slave: received end packet from server due to dump "
+                           "thread being killed on master. Dump threads are "
+                           "killed for example during master shutdown, "
+                           "explicitly by a user, or when the master receives "
+                           "a binlog send request from a duplicate server "
+                           "UUID <%s> : Error %s", ::server_uuid,
+                           mysql_error(mysql));
      DBUG_RETURN(packet_error);
   }
 
