bk commit into 5.1 tree (mats:1.2546) BUG#25688

[Mats Kindahl]

Below is the list of changes that have just been committed into a local
5.1 repository of mats. When mats does a push these changes will
be propagated to the main repository and, within 24 hours after the
push, to the public repository.
For information on how to access the public repository
see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html

ChangeSet@stripped, 2007-04-10 15:18:54+02:00, mats@romeo.(none) +6 -0
  BUG#25688 (RBR: circular replication may cause STMT_END_F flags to be
  skipped):
  
  By moving statement end actions from Rows_log_event::do_apply_event() to
  Rows_log_event::do_update_pos() they will always be executed, even if
  Rows_log_event::do_apply_event() is skipped because the event originated
  at the same server. This because Rows_log_event::do_update_pos() is always
  executed (unless Rows_log_event::do_apply_event() failed with an error,
  in which case the slave stops with an error anyway). 
  
  Adding test case.

  mysql-test/r/rpl_ndb_circular_simplex.result@stripped, 2007-04-10 15:18:51+02:00,
mats@romeo.(none) +61 -0
    New BitKeeper file ``mysql-test/r/rpl_ndb_circular_simplex.result''

  mysql-test/r/rpl_ndb_circular_simplex.result@stripped, 2007-04-10 15:18:51+02:00,
mats@romeo.(none) +0 -0

  mysql-test/t/rpl_ndb_circular_simplex.test@stripped, 2007-04-10 15:18:52+02:00,
mats@romeo.(none) +77 -0
    New BitKeeper file ``mysql-test/t/rpl_ndb_circular_simplex.test''

  mysql-test/t/rpl_ndb_circular_simplex.test@stripped, 2007-04-10 15:18:52+02:00,
mats@romeo.(none) +0 -0

  sql/log_event.cc@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +52 -72
    Moving statement end actions from Rows_log_event::do_apply_event() to
    Rows_log_event::do_update_pos().
    Factoring out code to update group positions and event positions into
    relay log info structure.

  sql/log_event.h@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +2 -0
    Adding Rows_log_event::do_update_pos().

  sql/rpl_rli.cc@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +45 -0
    Adding member function stmt_done() to do after-statement updates of the
    relay log info structure.

  sql/rpl_rli.h@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +22 -0
    Adding member function stmt_done() to do after-statement updates of the
    relay log info structure.

# This is a BitKeeper patch.  What follows are the unified diffs for the
# set of deltas contained in the patch.  The rest of the patch, the part
# that BitKeeper cares about, is below these diffs.
# User:	mats
# Host:	romeo.(none)
# Root:	/home/bk/b25688-mysql-5.1-rpl

--- 1.275/sql/log_event.cc	2007-04-10 15:19:04 +02:00
+++ 1.276/sql/log_event.cc	2007-04-10 15:19:04 +02:00
@@ -547,49 +547,7 @@
     Matz: I don't think we will need this check with this refactoring.
   */
   if (rli)
-  {
-    /*
-      If in a transaction, and if the slave supports transactions, just
-      inc_event_relay_log_pos(). We only have to check for OPTION_BEGIN
-      (not OPTION_NOT_AUTOCOMMIT) as transactions are logged with
-      BEGIN/COMMIT, not with SET AUTOCOMMIT= .
-
-      CAUTION: opt_using_transactions means
-      innodb || bdb ; suppose the master supports InnoDB and BDB,
-      but the slave supports only BDB, problems
-      will arise:
-      - suppose an InnoDB table is created on the master,
-      - then it will be MyISAM on the slave
-      - but as opt_using_transactions is true, the slave will believe he
-      is transactional with the MyISAM table. And problems will come
-      when one does START SLAVE; STOP SLAVE; START SLAVE; (the slave
-      will resume at BEGIN whereas there has not been any rollback).
-      This is the problem of using opt_using_transactions instead of a
-      finer "does the slave support
-      _the_transactional_handler_used_on_the_master_".
-
-      More generally, we'll have problems when a query mixes a
-      transactional handler and MyISAM and STOP SLAVE is issued in the
-      middle of the "transaction". START SLAVE will resume at BEGIN
-      while the MyISAM table has already been updated.
-    */
-    if ((thd->options & OPTION_BEGIN) && opt_using_transactions)
-      rli->inc_event_relay_log_pos();
-    else
-    {
-      rli->inc_group_relay_log_pos(log_pos);
-      flush_relay_log_info(rli);
-      /*
-         Note that Rotate_log_event::do_apply_event() does not call
-         this function, so there is no chance that a fake rotate event
-         resets last_master_timestamp.  Note that we update without
-         mutex (probably ok - except in some very rare cases, only
-         consequence is that value may take some time to display in
-         Seconds_Behind_Master - not critical).
-      */
-      rli->last_master_timestamp= when;
-    }
-  }
+    rli->stmt_done(thd, log_pos, when);
 
   return 0;                                   // Cannot fail currently
 }
@@ -6243,6 +6201,42 @@
     DBUG_RETURN(error);
   }
 
+  /*
+    This code would ideally be placed in do_update_pos() instead, but
+    since we have no access to table there, we do the setting of
+    last_event_start_time here instead.
+  */
+  if (table && (table->s->primary_key == MAX_KEY) &&
+      !cache_stmt && get_flags(STMT_END_F) == RLE_NO_FLAGS)
+  {
+    /*
+      ------------ Temporary fix until WL#2975 is implemented ---------
+
+      This event is not the last one (no STMT_END_F). If we stop now
+      (in case of terminate_slave_thread()), how will we restart? We
+      have to restart from Table_map_log_event, but as this table is
+      not transactional, the rows already inserted will still be
+      present, and idempotency is not guaranteed (no PK) so we risk
+      that repeating leads to double insert. So we desperately try to
+      continue, hope we'll eventually leave this buggy situation (by
+      executing the final Rows_log_event). If we are in a hopeless
+      wait (reached end of last relay log and nothing gets appended
+      there), we timeout after one minute, and notify DBA about the
+      problem.  When WL#2975 is implemented, just remove the member
+      st_relay_log_info::last_event_start_time and all its occurences.
+    */
+    const_cast<RELAY_LOG_INFO*>(rli)->last_event_start_time= time(0);
+  }
+
+  DBUG_RETURN(0);
+}
+
+int
+Rows_log_event::do_update_pos(RELAY_LOG_INFO *rli)
+{
+  DBUG_ENTER("Rows_log_event::do_update_pos");
+  int error= 0;
+
   if (get_flags(STMT_END_F))
   {
     /*
@@ -6261,6 +6255,7 @@
       replicate-ignore rules).
     */
     thd->binlog_flush_pending_rows_event(true);
+
     /*
       If this event is not in a transaction, the call below will, if some
       transactional storage engines are involved, commit the statement into
@@ -6271,6 +6266,7 @@
       binlog.
     */
     error= ha_autocommit_or_rollback(thd, 0);
+
     /*
       Now what if this is not a transactional engine? we still need to
       flush the pending event to the binlog; we did it with
@@ -6282,11 +6278,18 @@
     */
 
     thd->reset_current_stmt_binlog_row_based();
-    const_cast<RELAY_LOG_INFO*>(rli)->cleanup_context(thd, 0);
+    rli->cleanup_context(thd, 0);
 
     if (error == 0)
     {
       /*
+        Indicate that a statement is finished.
+        Step the group log position if we are not in a transaction,
+        otherwise increase the event log position.
+       */
+      rli->stmt_done(thd, log_pos, when);
+
+      /*
         Clear any errors pushed in thd->net.last_err* if for example "no key
         found" (as this is allowed). This is a safety measure; apparently
         those errors (e.g. when executing a Delete_rows_log_event of a
@@ -6298,38 +6301,15 @@
     }
     else
       slave_print_msg(ERROR_LEVEL, rli, error,
-                      "Error in %s event: commit of row events failed, "
-                      "table `%s`.`%s`",
-                      get_type_str(), table->s->db.str, 
-                      table->s->table_name.str);
-    DBUG_RETURN(error);
+                      "Error in %s event: commit of row events failed",
+                      get_type_str());
   }
-
-  if (table && (table->s->primary_key == MAX_KEY) && !cache_stmt)
+  else
   {
-    /*
-      ------------ Temporary fix until WL#2975 is implemented ---------
-
-      This event is not the last one (no STMT_END_F). If we stop now
-      (in case of terminate_slave_thread()), how will we restart? We
-      have to restart from Table_map_log_event, but as this table is
-      not transactional, the rows already inserted will still be
-      present, and idempotency is not guaranteed (no PK) so we risk
-      that repeating leads to double insert. So we desperately try to
-      continue, hope we'll eventually leave this buggy situation (by
-      executing the final Rows_log_event). If we are in a hopeless
-      wait (reached end of last relay log and nothing gets appended
-      there), we timeout after one minute, and notify DBA about the
-      problem.  When WL#2975 is implemented, just remove the member
-      st_relay_log_info::last_event_start_time and all its occurences.
-    */
-    const_cast<RELAY_LOG_INFO*>(rli)->last_event_start_time= time(0);
+    rli->inc_event_relay_log_pos();
   }
 
-  DBUG_ASSERT(error == 0);
-  thd->clear_error();
-
-  DBUG_RETURN(0);
+  DBUG_RETURN(error);
 }
 
 #endif /* !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION) */

--- 1.145/sql/log_event.h	2007-04-10 15:19:04 +02:00
+++ 1.146/sql/log_event.h	2007-04-10 15:19:04 +02:00
@@ -841,6 +841,7 @@
   }
 
 protected:
+
   /**
     Primitive to apply an event to the database.
 
@@ -2242,6 +2243,7 @@
 
 #if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION)
   virtual int do_apply_event(RELAY_LOG_INFO const *rli);
+  virtual int do_update_pos(RELAY_LOG_INFO *rli);
 
   /*
     Primitive to prepare for a sequence of row executions.

--- 1.7/sql/rpl_rli.cc	2007-04-10 15:19:05 +02:00
+++ 1.8/sql/rpl_rli.cc	2007-04-10 15:19:05 +02:00
@@ -1086,6 +1086,51 @@
 }
 
 
+void st_relay_log_info::stmt_done(THD *thd,
+                                  my_off_t const event_master_log_pos,
+                                  time_t event_creation_time)
+{
+  /*
+    If in a transaction, and if the slave supports transactions, just
+    inc_event_relay_log_pos(). We only have to check for OPTION_BEGIN
+    (not OPTION_NOT_AUTOCOMMIT) as transactions are logged with
+    BEGIN/COMMIT, not with SET AUTOCOMMIT= .
+
+    CAUTION: opt_using_transactions means innodb || bdb ; suppose the
+    master supports InnoDB and BDB, but the slave supports only BDB,
+    problems will arise: - suppose an InnoDB table is created on the
+    master, - then it will be MyISAM on the slave - but as
+    opt_using_transactions is true, the slave will believe he is
+    transactional with the MyISAM table. And problems will come when
+    one does START SLAVE; STOP SLAVE; START SLAVE; (the slave will
+    resume at BEGIN whereas there has not been any rollback).  This is
+    the problem of using opt_using_transactions instead of a finer
+    "does the slave support _transactional handler used on the
+    master_".
+
+    More generally, we'll have problems when a query mixes a
+    transactional handler and MyISAM and STOP SLAVE is issued in the
+    middle of the "transaction". START SLAVE will resume at BEGIN
+    while the MyISAM table has already been updated.
+  */
+  if ((thd->options & OPTION_BEGIN) && opt_using_transactions)
+    inc_event_relay_log_pos();
+  else
+  {
+    inc_group_relay_log_pos(event_master_log_pos);
+    flush_relay_log_info(this);
+    /*
+      Note that Rotate_log_event::do_apply_event() does not call this
+      function, so there is no chance that a fake rotate event resets
+      last_master_timestamp.  Note that we update without mutex
+      (probably ok - except in some very rare cases, only consequence
+      is that value may take some time to display in
+      Seconds_Behind_Master - not critical).
+    */
+    last_master_timestamp= event_creation_time;
+  }
+}
+
 #if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION)
 void st_relay_log_info::cleanup_context(THD *thd, bool error)
 {

--- 1.11/sql/rpl_rli.h	2007-04-10 15:19:05 +02:00
+++ 1.12/sql/rpl_rli.h	2007-04-10 15:19:05 +02:00
@@ -314,6 +314,28 @@
     transaction).
    */
   time_t last_event_start_time;
+
+  /**
+    Helper function to after statement completion.
+
+    This function will complete the group by stepping the group
+    position if the "statement" is not inside a transaction. If the
+    "statement" is inside a transaction, the function will just
+    increase the event position.
+
+    @param thd
+    Thread to use when deciding how to complete the statement
+
+    @param event_log_pos
+    Master log position of the event
+
+    @param event_creation_time
+    Timestamp for the creation of the event on the master side
+  */
+  void stmt_done(THD *thd,
+                 my_off_t event_log_pos,
+                 time_t event_creation_time);
+
 } RELAY_LOG_INFO;
 
 
--- New file ---
+++ mysql-test/r/rpl_ndb_circular_simplex.result	07/04/10 15:18:51
stop slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
reset master;
reset slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
start slave;
CREATE TABLE t1 (a int key, b int) ENGINE=NDB;
SHOW TABLES;
Tables_in_test
t1
RESET MASTER;
INSERT INTO t1 VALUES (1,2);
INSERT INTO t1 VALUES (2,3);
STOP SLAVE;
CHANGE MASTER TO MASTER_HOST="127.0.0.1",MASTER_PORT=SLAVE_PORT,MASTER_USER="root";
RESET MASTER;
START SLAVE;
SHOW SLAVE STATUS;
Slave_IO_State	#
Master_Host	127.0.0.1
Master_User	root
Master_Port	9308
Connect_Retry	60
Master_Log_File	slave-bin.000001
Read_Master_Log_Pos	468
Relay_Log_File	#
Relay_Log_Pos	#
Relay_Master_Log_File	slave-bin.000001
Slave_IO_Running	Yes
Slave_SQL_Running	Yes
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	468
Relay_Log_Space	#
Until_Condition	None
Until_Log_File	
Until_Log_Pos	0
Master_SSL_Allowed	No
Master_SSL_CA_File	
Master_SSL_CA_Path	
Master_SSL_Cert	
Master_SSL_Cipher	
Master_SSL_Key	
Seconds_Behind_Master	#
SELECT * FROM t1 ORDER BY a;
a	b
1	2
2	3
STOP SLAVE;
START SLAVE;
SELECT * FROM t1 ORDER BY a;
a	b
1	2
2	3

--- New file ---
+++ mysql-test/t/rpl_ndb_circular_simplex.test	07/04/10 15:18:52
--source include/have_ndb.inc
--source include/have_binlog_format_row.inc
--source include/master-slave.inc

connection master;
CREATE TABLE t1 (a int key, b int) ENGINE=NDB;
sync_slave_with_master;
SHOW TABLES;

# Lose the events from the slave binary log: there is no
# need to re-create the table on the master.
connection slave;
RESET MASTER;

# Insert some values on the slave and master
connection master;
INSERT INTO t1 VALUES (1,2);
# Switch to slave once event is applied and insert a row
sync_slave_with_master;
connection slave;
INSERT INTO t1 VALUES (2,3);

# ... it is now very probable that we have a mixed event in the binary
# log.  If we don't, the test should still pass, but will not test the
# mixed event situation.

# The statement is disabled since it cannot reliably show the same
# info all the time.  Use it for debug purposes.

#SHOW BINLOG EVENTS;

# Replicate back to the master to test this mixed event on the master
STOP SLAVE;

connection master;
--replace_result $SLAVE_MYPORT SLAVE_PORT
eval CHANGE MASTER TO
MASTER_HOST="127.0.0.1",MASTER_PORT=$SLAVE_MYPORT,MASTER_USER="root";

RESET MASTER;
START SLAVE;

connection slave;
save_master_pos;
connection master;
sync_with_master;

# The statement is disabled since it cannot reliably show the same
# info all the time.  Use it for debug purposes.

#SHOW BINLOG EVENTS;

# Check that there is no error in replication
--replace_result $MASTER_MYPORT MASTER_PORT
--replace_column 1 # 8 # 9 # 23 # 33 #
query_vertical SHOW SLAVE STATUS;

# Check that we have the data on the master
SELECT * FROM t1 ORDER BY a;

# We should now have another mixed event, likely with "slave" server
# id last, and with the STMT_END_F flag set.

# The statement is disabled since it cannot reliably show the same
# info all the time.  Use it for debug purposes.

#SHOW BINLOG EVENTS;

# now lets see that this data is applied correctly on the slave
STOP SLAVE;
save_master_pos;

connection slave;
START SLAVE;

# check that we have the data on the slave
sync_with_master;
SELECT * FROM t1 ORDER BY a;