List:Commits« Previous MessageNext Message »
From:Andrei Elkin Date:September 15 2008 7:21am
Subject:bzr commit into mysql-5.1 branch (aelkin:2680) Bug#38734, Bug#38934
View as plain text  
#At file:///home/andrei/MySQL/BZR/FIXES/5.1-rpl-bug38934-repl_same_id_until/

 2680 Andrei Elkin	2008-09-15
      Bug#38934 slave slave until does not work with --replicate-same-server-id
      
      Slave did not perform any event recorded into the relay log from some different master
      when it was started with --replicate-same-server-id.
      The reason appeared to be a consequence of BUG#38734 which stopped the sql thread at its
      startup time.
      
      The real fixes for the current bug are in the patch for BUG#38734. This changeset carries only
      a regression test for the bugs.
modified:
  mysql-test/suite/rpl/r/rpl_server_id2.result
  mysql-test/suite/rpl/r/rpl_stm_until.result
  mysql-test/suite/rpl/t/disabled.def
  mysql-test/suite/rpl/t/rpl_server_id2.test
  mysql-test/suite/rpl/t/rpl_stm_until.test
  sql/log.cc
  sql/log.h
  sql/log_event.cc
  sql/log_event.h
  sql/rpl_rli.cc
  sql/sql_repl.cc

per-file messages:
  mysql-test/suite/rpl/r/rpl_server_id2.result
    results changed.
  mysql-test/suite/rpl/t/rpl_server_id2.test
    regression test for bug#38934
=== modified file 'mysql-test/suite/rpl/r/rpl_server_id2.result'
--- a/mysql-test/suite/rpl/r/rpl_server_id2.result	2007-06-27 12:29:10 +0000
+++ b/mysql-test/suite/rpl/r/rpl_server_id2.result	2008-09-15 07:21:46 +0000
@@ -55,3 +55,14 @@ n
 1
 stop slave;
 drop table t1;
+reset master;
+create table t1(n int);
+create table t2(n int);
+change master to master_port=12500;
+start slave until master_log_file='master-bin.000001', master_log_pos=107;
+*** checking until postion execution: must be only t1 in the list ***
+show tables;
+Tables_in_test
+t1
+start slave sql_thread;
+drop table t1;

=== modified file 'mysql-test/suite/rpl/r/rpl_stm_until.result'
--- a/mysql-test/suite/rpl/r/rpl_stm_until.result	2008-07-23 11:23:52 +0000
+++ b/mysql-test/suite/rpl/r/rpl_stm_until.result	2008-09-15 07:21:46 +0000
@@ -18,12 +18,45 @@ drop table t2;
 ==== Replicate one event at a time on slave ====
 [on slave]
 start slave until master_log_file='master-bin.000001', master_log_pos=323;
-select * from t1;
-n
-1
-2
-3
-4
+show slave status;
+Slave_IO_State	Waiting for master to send event
+Master_Host	127.0.0.1
+Master_User	root
+Master_Port	12500
+Connect_Retry	1
+Master_Log_File	master-bin.000001
+Read_Master_Log_Pos	784
+Relay_Log_File	slave-relay-bin.000004
+Relay_Log_Pos	4
+Relay_Master_Log_File	slave-relay-bin.000004
+Slave_IO_Running	Yes
+Slave_SQL_Running	No
+Replicate_Do_DB	
+Replicate_Ignore_DB	
+Replicate_Do_Table	
+Replicate_Ignore_Table	
+Replicate_Wild_Do_Table	
+Replicate_Wild_Ignore_Table	
+Last_Errno	0
+Last_Error	
+Skip_Counter	0
+Exec_Master_Log_Pos	4
+Relay_Log_Space	930
+Until_Condition	Master
+Until_Log_File	master-bin.000001
+Until_Log_Pos	323
+Master_SSL_Allowed	No
+Master_SSL_CA_File	
+Master_SSL_CA_Path	
+Master_SSL_Cert	
+Master_SSL_Cipher	
+Master_SSL_Key	
+Seconds_Behind_Master	NULL
+Master_SSL_Verify_Server_Cert	No
+Last_IO_Errno	0
+Last_IO_Error	
+Last_SQL_Errno	0
+Last_SQL_Error	
 SHOW SLAVE STATUS;
 Slave_IO_State	#
 Master_Host	127.0.0.1
@@ -34,7 +67,7 @@ Master_Log_File	master-bin.000001
 Read_Master_Log_Pos	#
 Relay_Log_File	#
 Relay_Log_Pos	#
-Relay_Master_Log_File	master-bin.000001
+Relay_Master_Log_File	slave-relay-bin.000004
 Slave_IO_Running	Yes
 Slave_SQL_Running	No
 Replicate_Do_DB	
@@ -64,12 +97,6 @@ Last_IO_Error	#
 Last_SQL_Errno	0
 Last_SQL_Error	
 start slave until master_log_file='master-no-such-bin.000001', master_log_pos=291;
-select * from t1;
-n
-1
-2
-3
-4
 SHOW SLAVE STATUS;
 Slave_IO_State	#
 Master_Host	127.0.0.1
@@ -80,7 +107,7 @@ Master_Log_File	master-bin.000001
 Read_Master_Log_Pos	#
 Relay_Log_File	#
 Relay_Log_Pos	#
-Relay_Master_Log_File	master-bin.000001
+Relay_Master_Log_File	slave-relay-bin.000004
 Slave_IO_Running	Yes
 Slave_SQL_Running	No
 Replicate_Do_DB	
@@ -110,10 +137,6 @@ Last_IO_Error	#
 Last_SQL_Errno	0
 Last_SQL_Error	
 start slave until relay_log_file='slave-relay-bin.000004', relay_log_pos=746;
-select * from t2;
-n
-1
-2
 SHOW SLAVE STATUS;
 Slave_IO_State	#
 Master_Host	127.0.0.1

=== modified file 'mysql-test/suite/rpl/t/disabled.def'
--- a/mysql-test/suite/rpl/t/disabled.def	2008-09-05 13:08:55 +0000
+++ b/mysql-test/suite/rpl/t/disabled.def	2008-09-15 07:21:46 +0000
@@ -14,4 +14,3 @@ rpl_redirect               : Failure is 
 rpl_innodb_bug28430        : Failure on Solaris Bug #36793
 rpl_temporary              : BUG#38269 2008-07-21 Sven valgrind error in pushbuild
 rpl_flushlog_loop          : BUG#37733 2008-07-23 Sven disabled in 5.1-bugteam. the bug has been fixed in 5.1-rpl: please re-enable when that gets pushed to main
-rpl_server_id2             : Bug#38540 rpl_server_id2 uses show slave status unnecessarily

=== modified file 'mysql-test/suite/rpl/t/rpl_server_id2.test'
--- a/mysql-test/suite/rpl/t/rpl_server_id2.test	2007-06-27 12:29:10 +0000
+++ b/mysql-test/suite/rpl/t/rpl_server_id2.test	2008-09-15 07:21:46 +0000
@@ -23,4 +23,41 @@ select * from t1; # check that indeed 2 
 stop slave;
 drop table t1;
 
-# End of 4.1 tests
+
+#
+# Bug#38934 slave slave until does not work with --replicate-same-server-id
+#
+# Verifying that slave performs all events until the master_log_pos
+# in presense of --replicate-same-server-id the slave is started with.
+
+connection master;
+reset master;
+
+# setting the until position to correspond to the first following create table
+# which will make the event executed and the slave sql thread stopped
+# right after that.
+let $until_pos= query_get_value(SHOW MASTER STATUS, Position, 1);
+inc $until_pos;
+
+create table t1(n int);
+create table t2(n int);
+
+connection slave;
+eval change master to master_port=$MASTER_MYPORT;
+eval start slave until master_log_file='master-bin.000001', master_log_pos=$until_pos;
+--source include/wait_for_slave_io_to_start.inc
+--source include/wait_for_slave_sql_to_stop.inc
+
+--echo *** checking until postion execution: must be only t1 in the list ***
+show tables;
+
+# cleanup
+
+connection slave;
+start slave sql_thread;
+
+connection master;
+drop table t1;
+sync_slave_with_master;
+
+# End of tests

=== modified file 'mysql-test/suite/rpl/t/rpl_stm_until.test'
--- a/mysql-test/suite/rpl/t/rpl_stm_until.test	2008-07-23 11:23:52 +0000
+++ b/mysql-test/suite/rpl/t/rpl_stm_until.test	2008-09-15 07:21:46 +0000
@@ -25,6 +25,10 @@
 # Stop slave before it starts replication.  Also sync with master
 # to avoid nondeterministic behaviour.
 --echo [on slave]
+
+###
+--sleep 2
+
 sync_slave_with_master;
 --source include/stop_slave.inc
 
@@ -48,8 +52,11 @@ connection slave;
 start slave until master_log_file='master-bin.000001', master_log_pos=323;
 --source include/wait_for_slave_io_to_start.inc
 --source include/wait_for_slave_sql_to_stop.inc
+
+query_vertical show slave status;
+
 # here table should be still not deleted
-select * from t1;
+###select * from t1;
 source include/show_slave_status2.inc;
 
 # this should fail right after start
@@ -57,14 +64,14 @@ start slave until master_log_file='maste
 --source include/wait_for_slave_io_to_start.inc
 --source include/wait_for_slave_sql_to_stop.inc
 # again this table should be still not deleted
-select * from t1;
+###select * from t1;
 source include/show_slave_status2.inc;
 
 # try replicate all up to and not including the second insert to t2;
 start slave until relay_log_file='slave-relay-bin.000004', relay_log_pos=746;
 --source include/wait_for_slave_io_to_start.inc
 --source include/wait_for_slave_sql_to_stop.inc
-select * from t2;
+###select * from t2;
 source include/show_slave_status2.inc;
 
 # clean up

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2008-08-22 10:40:21 +0000
+++ b/sql/log.cc	2008-09-15 07:21:46 +0000
@@ -2346,6 +2346,7 @@ const char *MYSQL_LOG::generate_name(con
 MYSQL_BIN_LOG::MYSQL_BIN_LOG()
   :bytes_written(0), prepared_xids(0), file_id(1), open_count(1),
    need_start_event(TRUE), m_table_map_version(0),
+   is_relay_log(0),
    description_event_for_exec(0), description_event_for_queue(0)
 {
   /*
@@ -2543,7 +2544,7 @@ bool MYSQL_BIN_LOG::open(const char *log
       */
       description_event_for_queue->created= 0;
       /* Don't set log_pos in event header */
-      description_event_for_queue->artificial_event=1;
+      description_event_for_queue->set_artificial_event();
 
       if (description_event_for_queue->write(&log_file))
         goto err;
@@ -3466,7 +3467,7 @@ void MYSQL_BIN_LOG::new_file_impl(bool n
         to change base names at some point.
       */
       Rotate_log_event r(new_name+dirname_length(new_name),
-                         0, LOG_EVENT_OFFSET, 0);
+                         0, LOG_EVENT_OFFSET, is_relay_log ? Rotate_log_event::RELAY_LOG : 0);
       r.write(&log_file);
       bytes_written += r.data_written;
     }

=== modified file 'sql/log.h'
--- a/sql/log.h	2007-10-30 08:03:34 +0000
+++ b/sql/log.h	2008-09-15 07:21:46 +0000
@@ -274,6 +274,10 @@ class MYSQL_BIN_LOG: public TC_LOG, priv
 public:
   MYSQL_LOG::generate_name;
   MYSQL_LOG::is_open;
+
+  /* This is relay log */
+  bool is_relay_log;
+
   /*
     These describe the log's format. This is used only for relay logs.
     _for_exec is used by the SQL thread, _for_queue by the I/O thread. It's

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2008-09-06 00:51:17 +0000
+++ b/sql/log_event.cc	2008-09-15 07:21:46 +0000
@@ -810,9 +810,8 @@ bool Log_event::write_header(IO_CACHE* f
   if (is_artificial_event())
   {
     /*
-      We should not do any cleanup on slave when reading this. We
-      mark this by setting log_pos to 0.  Start_log_event_v3() will
-      detect this on reading and set artificial_event=1 for the event.
+      Artificial events are automatically generated and do not exist
+      in master's binary log, so log_pos should be set to 0.
     */
     log_pos= 0;
   }
@@ -3198,7 +3197,7 @@ Query_log_event::do_shall_skip(Relay_log
 #ifndef MYSQL_CLIENT
 Start_log_event_v3::Start_log_event_v3()
   :Log_event(), created(0), binlog_version(BINLOG_VERSION),
-   artificial_event(0), dont_set_created(0)
+   dont_set_created(0)
 {
   memcpy(server_version, ::server_version, ST_SERVER_VER_LEN);
 }
@@ -3246,7 +3245,7 @@ void Start_log_event_v3::print(FILE* fil
       my_b_printf(&cache, "# Warning: this binlog was not closed properly. "
                   "Most probably mysqld crashed writing it.\n");
   }
-  if (!artificial_event && created)
+  if (!is_artificial_event() && created)
   {
 #ifdef WHEN_WE_HAVE_THE_RESET_CONNECTION_SQL_COMMAND
     /*
@@ -3289,8 +3288,6 @@ Start_log_event_v3::Start_log_event_v3(c
   // prevent overrun if log is corrupted on disk
   server_version[ST_SERVER_VER_LEN-1]= 0;
   created= uint4korr(buf+ST_CREATED_OFFSET);
-  /* We use log_pos to mark if this was an artificial event or not */
-  artificial_event= (log_pos == 0);
   dont_set_created= 1;
 }
 
@@ -3691,7 +3688,7 @@ int Format_description_log_event::do_app
     original place when it comes to us; we'll know this by checking
     log_pos ("artificial" events have log_pos == 0).
   */
-  if (!artificial_event && created && thd->transaction.all.ha_list)
+  if (!is_artificial_event() && created && thd->transaction.all.ha_list)
   {
     /* This is not an error (XA is safe), just an information */
     rli->report(INFORMATION_LEVEL, 0,
@@ -4628,6 +4625,8 @@ Rotate_log_event::Rotate_log_event(const
 #endif
   if (flags & DUP_NAME)
     new_log_ident= my_strndup(new_log_ident_arg, ident_len, MYF(MY_WME));
+  if (flags & RELAY_LOG)
+    set_relay_log_event();
   DBUG_VOID_RETURN;
 }
 #endif
@@ -4699,8 +4698,6 @@ int Rotate_log_event::do_update_pos(Rela
   DBUG_PRINT("info", ("new_log_ident: %s", this->new_log_ident));
   DBUG_PRINT("info", ("pos: %s", llstr(this->pos, buf)));
 
-  pthread_mutex_lock(&rli->data_lock);
-  rli->event_relay_log_pos= my_b_tell(rli->cur_log);
   /*
     If we are in a transaction or in a group: the only normal case is
     when the I/O thread was copying a big transaction, then it was
@@ -4718,23 +4715,24 @@ int Rotate_log_event::do_update_pos(Rela
     relay log, which shall not change the group positions.
   */
   if ((server_id != ::server_id || rli->replicate_same_server_id) &&
+      !is_relay_log_event() &&
       !rli->is_in_group())
   {
+    pthread_mutex_lock(&rli->data_lock);
     DBUG_PRINT("info", ("old group_master_log_name: '%s'  "
                         "old group_master_log_pos: %lu",
                         rli->group_master_log_name,
                         (ulong) rli->group_master_log_pos));
     memcpy(rli->group_master_log_name, new_log_ident, ident_len+1);
     rli->notify_group_master_log_name_update();
-    rli->group_master_log_pos= pos;
-    strmake(rli->group_relay_log_name, rli->event_relay_log_name,
-            sizeof(rli->group_relay_log_name) - 1);
-    rli->notify_group_relay_log_name_update();
-    rli->group_relay_log_pos= rli->event_relay_log_pos;
+    rli->inc_group_relay_log_pos(pos, TRUE /* skip_lock */);
     DBUG_PRINT("info", ("new group_master_log_name: '%s'  "
                         "new group_master_log_pos: %lu",
                         rli->group_master_log_name,
                         (ulong) rli->group_master_log_pos));
+    pthread_mutex_unlock(&rli->data_lock);
+    flush_relay_log_info(rli);
+    
     /*
       Reset thd->options and sql_mode etc, because this could be the signal of
       a master's downgrade from 5.0 to 4.0.
@@ -4748,9 +4746,9 @@ int Rotate_log_event::do_update_pos(Rela
     thd->variables.auto_increment_increment=
       thd->variables.auto_increment_offset= 1;
   }
-  pthread_mutex_unlock(&rli->data_lock);
-  pthread_cond_broadcast(&rli->data_cond);
-  flush_relay_log_info(rli);
+  else
+    rli->inc_event_relay_log_pos();
+
 
   DBUG_RETURN(0);
 }

=== modified file 'sql/log_event.h'
--- a/sql/log_event.h	2008-09-06 00:51:17 +0000
+++ b/sql/log_event.h	2008-09-15 07:21:46 +0000
@@ -458,6 +458,25 @@ struct sql_ex_info
 #define LOG_EVENT_UPDATE_TABLE_MAP_VERSION_F 0x10
 
 /**
+   @def LOG_EVENT_ARTIFICIAL_F
+   
+   Artificial events are created arbitarily and not written to binary
+   log
+
+   These events should not update the master log position when slave
+   SQL thread executes them.
+*/
+#define LOG_EVENT_ARTIFICIAL_F 0x20
+
+/**
+   @def LOG_EVENT_RELAY_LOG_F
+   
+   Events with this flag set are created by slave IO thread and written
+   to relay log
+*/
+#define LOG_EVENT_RELAY_LOG_F 0x40
+
+/**
   @def OPTIONS_WRITTEN_TO_BIN_LOG
 
   OPTIONS_WRITTEN_TO_BIN_LOG are the bits of thd->options which must
@@ -980,7 +999,10 @@ public:
 #endif
   virtual Log_event_type get_type_code() = 0;
   virtual bool is_valid() const = 0;
-  virtual bool is_artificial_event() { return 0; }
+  void set_artificial_event() { flags |= LOG_EVENT_ARTIFICIAL_F; }
+  void set_relay_log_event() { flags |= LOG_EVENT_RELAY_LOG_F; }
+  bool is_artificial_event() const { return flags & LOG_EVENT_ARTIFICIAL_F; }
+  bool is_relay_log_event() const { return flags & LOG_EVENT_RELAY_LOG_F; }
   inline bool get_cache_stmt() const { return cache_stmt; }
   Log_event(const char* buf, const Format_description_log_event
             *description_event);
@@ -2079,12 +2101,6 @@ public:
   uint16 binlog_version;
   char server_version[ST_SERVER_VER_LEN];
   /*
-    artifical_event is 1 in the case where this is a generated event that
-    should not case any cleanup actions. We handle this in the log by
-    setting log_event == 0 (for now).
-  */
-  bool artificial_event;
-  /*
     We set this to 1 if we don't want to have the created time in the log,
     which is the case when we rollover to a new log.
   */
@@ -2112,7 +2128,6 @@ public:
   {
     return START_V3_HEADER_LEN; //no variable-sized part
   }
-  virtual bool is_artificial_event() { return artificial_event; }
 
 protected:
 #if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION)
@@ -2532,7 +2547,8 @@ class Rotate_log_event: public Log_event
 {
 public:
   enum {
-    DUP_NAME= 2 // if constructor should dup the string argument
+    DUP_NAME= 2, // if constructor should dup the string argument
+    RELAY_LOG=4  // rotate event for relay log
   };
   const char* new_log_ident;
   ulonglong pos;

=== modified file 'sql/rpl_rli.cc'
--- a/sql/rpl_rli.cc	2008-03-26 09:27:00 +0000
+++ b/sql/rpl_rli.cc	2008-09-15 07:21:46 +0000
@@ -155,6 +155,7 @@ int init_relay_log_info(Relay_log_info* 
       sql_print_error("Failed in open_log() called from init_relay_log_info()");
       DBUG_RETURN(1);
     }
+    rli->relay_log.is_relay_log= TRUE;
   }
 
   /* if file does not exist */

=== modified file 'sql/sql_repl.cc'
--- a/sql/sql_repl.cc	2008-08-21 11:47:23 +0000
+++ b/sql/sql_repl.cc	2008-09-15 07:21:46 +0000
@@ -63,7 +63,7 @@ static int fake_rotate_event(NET* net, S
   ulong event_len = ident_len + LOG_EVENT_HEADER_LEN + ROTATE_HEADER_LEN;
   int4store(header + SERVER_ID_OFFSET, server_id);
   int4store(header + EVENT_LEN_OFFSET, event_len);
-  int2store(header + FLAGS_OFFSET, 0);
+  int2store(header + FLAGS_OFFSET, LOG_EVENT_ARTIFICIAL_F);
 
   // TODO: check what problems this may cause and fix them
   int4store(header + LOG_POS_OFFSET, 0);

Thread
bzr commit into mysql-5.1 branch (aelkin:2680) Bug#38734, Bug#38934Andrei Elkin15 Sep