bk commit into 5.1 tree (mats:1.2547) 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 21:43:42+02:00, mats@romeo.(none) +2 -0
  BUG#25688 (RBR: circular replication may cause STMT_END_F flags to be skipped):
  
  Fixing logic to detect if inside a group. If a rotate event occured when
  an initial prefix of events for a statement, but for which the table
  did contain a key, last_event_start_time is set to zero, causing rotate
  to end the group but without unlocking any tables. This left a lock
  hanging around, which subsequently triggered an assertion when a second
  attempt was made to lock the same sequence of tables. 

  sql/log_event.cc@stripped, 2007-04-10 21:43:38+02:00, mats@romeo.(none) +19 -4
    Adding debugging printouts.
    Fixing logic to detect if inside a group.

  sql/slave.cc@stripped, 2007-04-10 21:43:38+02:00, mats@romeo.(none) +20 -19
    Adding debuging printouts.

# 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.276/sql/log_event.cc	2007-04-10 21:43:52 +02:00
+++ 1.277/sql/log_event.cc	2007-04-10 21:43:52 +02:00
@@ -31,6 +31,8 @@
 
 #define log_cs	&my_charset_latin1
 
+#define FLAGSTR(V,F) ((V)&(F)?#F" ":"")
+
 /*
   Cache that will automatically be written to a dedicated file on
   destruction.
@@ -982,6 +984,10 @@
     break;
   }
 
+  DBUG_PRINT("read_event", ("%s(type_code: %d; event_len: %d)",
+                            ev ? ev->get_type_str() : "<unknown>",
+                            buf[EVENT_TYPE_OFFSET],
+                            event_len));
   /*
     is_valid() are small event-specific sanity tests which are
     important; for example there are some my_malloc() in constructors
@@ -3538,12 +3544,16 @@
 
 /**
    Helper function to detect if the event is inside a group.
+
+   We are inside a group if either:
+   - The OPTION_BEGIN flag is set, meaning that we're inside a transaction
+   - There are locks held, meaning that we're inside a statement
  */
 #if defined(HAVE_REPLICATION) && !defined(MYSQL_CLIENT)
-static bool is_in_group(THD *const thd, RELAY_LOG_INFO *const rli)
+static bool is_in_group(THD *const thd)
 {
   return (thd->options & OPTION_BEGIN) != 0 ||
-         (rli->last_event_start_time > 0);
+         (thd->lock != NULL);
 }
 #endif
 
@@ -3597,7 +3607,7 @@
     relay log, which shall not change the group positions.
   */
   if ((server_id != ::server_id || rli->replicate_same_server_id) &&
-      !is_in_group(thd, rli))
+      !is_in_group(thd))
   {
     DBUG_PRINT("info", ("old group_master_log_name: '%s'  "
                         "old group_master_log_pos: %lu",
@@ -6237,6 +6247,9 @@
   DBUG_ENTER("Rows_log_event::do_update_pos");
   int error= 0;
 
+  DBUG_PRINT("info", ("flags: %s",
+                      get_flags(STMT_END_F) ? "STMT_END_F " : ""));
+
   if (get_flags(STMT_END_F))
   {
     /*
@@ -6393,7 +6406,9 @@
   {
     bool const last_stmt_event= get_flags(STMT_END_F);
     print_header(head, print_event_info, !last_stmt_event);
-    my_b_printf(head, "\t%s: table id %lu\n", name, m_table_id);
+    my_b_printf(head, "\t%s: table id %lu%s\n",
+                name, m_table_id,
+                last_stmt_event ? " flags: STMT_END_F" : "");
     print_base64(body, print_event_info, !last_stmt_event);
   }
 

--- 1.300/sql/slave.cc	2007-04-10 21:43:52 +02:00
+++ 1.301/sql/slave.cc	2007-04-10 21:43:52 +02:00
@@ -1731,11 +1731,12 @@
     /*
     */
 
-    DBUG_PRINT("info",("type_code=%d (%s), server_id=%d",
-                       type_code, ev->get_type_str(), ev->server_id));
-    DBUG_PRINT("info", ("thd->options={ %s%s}",
+    DBUG_PRINT("exec_event",("%s(type_code: %d; server_id: %d)",
+                       ev->get_type_str(), type_code, ev->server_id));
+    DBUG_PRINT("info", ("thd->options: %s%s; rli->last_event_start_time: %lu",
                         FLAGSTR(thd->options, OPTION_NOT_AUTOCOMMIT),
-                        FLAGSTR(thd->options, OPTION_BEGIN)));
+                        FLAGSTR(thd->options, OPTION_BEGIN),
+                        rli->last_event_start_time));
 
 
 
@@ -1777,21 +1778,21 @@
     if (reason == Log_event::EVENT_SKIP_NOT)
       exec_res= ev->apply_event(rli);
 #ifndef DBUG_OFF
-    else
-    {
-      /*
-        This only prints information to the debug trace.
-
-        TODO: Print an informational message to the error log?
-       */
-      static const char *const explain[] = {
-        "event was not skipped",                  // EVENT_SKIP_NOT,
-        "event originated from this server",      // EVENT_SKIP_IGNORE,
-        "event skip counter was non-zero"         // EVENT_SKIP_COUNT
-      };
-      DBUG_PRINT("info", ("%s was skipped because %s",
-                          ev->get_type_str(), explain[reason]));
-    }
+    /*
+      This only prints information to the debug trace.
+
+      TODO: Print an informational message to the error log?
+    */
+    static const char *const explain[] = {
+      // EVENT_SKIP_NOT,
+      "not skipped",
+      // EVENT_SKIP_IGNORE,
+      "skipped because event originated from this server",
+      // EVENT_SKIP_COUNT
+      "skipped because event skip counter was non-zero"
+    };
+    DBUG_PRINT("skip_event", ("%s event was %s",
+                              ev->get_type_str(), explain[reason]));
 #endif
 
     DBUG_PRINT("info", ("apply_event error = %d", exec_res));