BUG#23171: Illegal group log position

Tail fixes after re-applying patches to older version of clone.

sql/log_event.cc

@@ -596,14 +596,20 @@ int Log_event::do_update_pos(RELAY_LOG_INFO *rli)
 
 
 Log_event::enum_skip_reason
-Log_event::shall_skip(RELAY_LOG_INFO *rli)
-{
-  if (this->server_id == ::server_id && !replicate_same_server_id)
-    return EVENT_SKIP_SAME_SID;
+Log_event::do_shall_skip(RELAY_LOG_INFO *rli)
+{
+  DBUG_PRINT("info", ("ev->server_id=%lu, ::server_id=%lu,"
+                      " rli->replicate_same_server_id=%d,"
+                      " rli->slave_skip_counter=%d",
+                      (ulong) server_id, (ulong) ::server_id,
+                      rli->replicate_same_server_id,
+                      rli->slave_skip_counter));
+  if (server_id == ::server_id && !rli->replicate_same_server_id)
+    return EVENT_SKIP_IGNORE;
   else if (rli->slave_skip_counter > 0)
     return EVENT_SKIP_COUNT;
   else
-    return EVENT_NOT_SKIPPED;
+    return EVENT_SKIP_NOT;
 }
 
 
@@ -2566,9 +2572,9 @@ int Format_description_log_event::do_update_pos(RELAY_LOG_INFO *rli)
 }
 
 Log_event::enum_skip_reason
-Format_description_log_event::shall_skip(RELAY_LOG_INFO *rli)
+Format_description_log_event::do_shall_skip(RELAY_LOG_INFO *rli)
 {
-  return Log_event::EVENT_NOT_SKIPPED;
+  return Log_event::EVENT_SKIP_NOT;
 }
 
 #endif
@@ -3077,7 +3083,7 @@ void Load_log_event::set_fields(const char* affected_db,
 */
 
 int Load_log_event::do_apply_event(NET* net, RELAY_LOG_INFO const *rli,
-                                     bool use_rli_only_for_errors)
+                                   bool use_rli_only_for_errors)
 {
   LEX_STRING new_db;
   new_db.length= db_len;
@@ -3416,6 +3422,7 @@ Rotate_log_event::Rotate_log_event(const char* buf, uint event_len,
   ident_offset = post_header_len; 
   set_if_smaller(ident_len,FN_REFLEN-1);
   new_log_ident= my_strndup(buf + ident_offset, (uint) ident_len, MYF(MY_WME));
+  DBUG_PRINT("debug", ("new_log_ident: '%s'", new_log_ident));
   DBUG_VOID_RETURN;
 }
 
@@ -3438,11 +3445,13 @@ bool Rotate_log_event::write(IO_CACHE* file)
 /**
    Helper function to detect if the event is inside a group.
  */
+#if defined(HAVE_REPLICATION) && !defined(MYSQL_CLIENT)
 static bool is_in_group(THD *const thd, RELAY_LOG_INFO *const rli)
 {
   return (thd->options & OPTION_BEGIN) != 0 ||
          (rli->last_event_start_time > 0);
 }
+#endif
 
 
 /*
@@ -3470,7 +3479,8 @@ int Rotate_log_event::do_update_pos(RELAY_LOG_INFO *rli)
   char buf[32];
 #endif
 
-  DBUG_PRINT("info", ("server_id=%lu; ::server_id=%lu", this->server_id, ::server_id));
+  DBUG_PRINT("info", ("server_id=%lu; ::server_id=%lu",
+                      (ulong) this->server_id, (ulong) ::server_id));
   DBUG_PRINT("info", ("new_log_ident: %s", this->new_log_ident));
   DBUG_PRINT("info", ("pos: %s", llstr(this->pos, buf)));
 
@@ -3490,10 +3500,15 @@ int Rotate_log_event::do_update_pos(RELAY_LOG_INFO *rli)
     In that case, we don't want to touch the coordinates which
     correspond to the beginning of the transaction.  Starting from
     5.0.0, there also are some rotates from the slave itself, in the
-    relay log.
+    relay log, which shall not change the group positions.
   */
-  if (!is_in_group(thd, rli))
+  if ((server_id != ::server_id || rli->replicate_same_server_id) &&
+      !is_in_group(thd, rli))
   {
+    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;
@@ -3524,18 +3539,17 @@ int Rotate_log_event::do_update_pos(RELAY_LOG_INFO *rli)
 
 
 Log_event::enum_skip_reason
-Rotate_log_event::shall_skip(RELAY_LOG_INFO *rli)
+Rotate_log_event::do_shall_skip(RELAY_LOG_INFO *rli)
 {
-  
-  enum_skip_reason reason= Log_event::shall_skip(rli);
+  enum_skip_reason reason= Log_event::do_shall_skip(rli);
 
   switch (reason) {
-  case Log_event::EVENT_NOT_SKIPPED:
+  case Log_event::EVENT_SKIP_NOT:
   case Log_event::EVENT_SKIP_COUNT:
-    return Log_event::EVENT_NOT_SKIPPED;
+    return Log_event::EVENT_SKIP_NOT;
 
-  case Log_event::EVENT_SKIP_SAME_SID:
-    return Log_event::EVENT_SKIP_SAME_SID;
+  case Log_event::EVENT_SKIP_IGNORE:
+    return Log_event::EVENT_SKIP_IGNORE;
   }
   DBUG_ASSERT(0);
 }
@@ -3671,21 +3685,20 @@ int Intvar_log_event::do_update_pos(RELAY_LOG_INFO *rli)
 
 
 Log_event::enum_skip_reason
-Intvar_log_event::shall_skip(RELAY_LOG_INFO *rli)
+Intvar_log_event::do_shall_skip(RELAY_LOG_INFO *rli)
 {
   /*
-    It is a common error to set the slave skip counter to 1 instead
-    of 2 when recovering from an insert which used a auto increment,
-    rand, or user var.  Therefore, if the slave skip counter is 1,
-    we just say that this event should be skipped because of the
-    slave skip count, but we do not change the value of the slave
-    skip counter since it will be decreased by the following insert
-    event.
+    It is a common error to set the slave skip counter to 1 instead of
+    2 when recovering from an insert which used a auto increment,
+    rand, or user var.  Therefore, if the slave skip counter is 1, we
+    just say that this event should be skipped by ignoring it, meaning
+    that we do not change the value of the slave skip counter since it
+    will be decreased by the following insert event.
   */
   if (rli->slave_skip_counter == 1)
-    return Log_event::EVENT_SKIP_COUNT;
+    return Log_event::EVENT_SKIP_IGNORE;
   else
-    return Log_event::shall_skip(rli);
+    return Log_event::do_shall_skip(rli);
 }
 
 #endif
@@ -3764,21 +3777,20 @@ int Rand_log_event::do_update_pos(RELAY_LOG_INFO *rli)
 
 
 Log_event::enum_skip_reason
-Rand_log_event::shall_skip(RELAY_LOG_INFO *rli)
+Rand_log_event::do_shall_skip(RELAY_LOG_INFO *rli)
 {
   /*
-    It is a common error to set the slave skip counter to 1 instead
-    of 2 when recovering from an insert which used a auto increment,
-    rand, or user var.  Therefore, if the slave skip counter is 1,
-    we just say that this event should be skipped because of the
-    slave skip count, but we do not change the value of the slave
-    skip counter since it will be decreased by the following insert
-    event.
+    It is a common error to set the slave skip counter to 1 instead of
+    2 when recovering from an insert which used a auto increment,
+    rand, or user var.  Therefore, if the slave skip counter is 1, we
+    just say that this event should be skipped by ignoring it, meaning
+    that we do not change the value of the slave skip counter since it
+    will be decreased by the following insert event.
   */
   if (rli->slave_skip_counter == 1)
-    return Log_event::EVENT_SKIP_COUNT;
+    return Log_event::EVENT_SKIP_IGNORE;
   else
-    return Log_event::shall_skip(rli);
+    return Log_event::do_shall_skip(rli);
 }
 
 #endif /* !MYSQL_CLIENT */
@@ -4204,22 +4216,21 @@ int User_var_log_event::do_update_pos(RELAY_LOG_INFO *rli)
 }
 
 Log_event::enum_skip_reason
-User_var_log_event::shall_skip(RELAY_LOG_INFO *rli)
-  {
-    /*
-      It is a common error to set the slave skip counter to 1 instead
-      of 2 when recovering from an insert which used a auto increment,
-      rand, or user var.  Therefore, if the slave skip counter is 1,
-      we just say that this event should be skipped because of the
-      slave skip count, but we do not change the value of the slave
-      skip counter since it will be decreased by the following insert
-      event.
-    */
-    if (rli->slave_skip_counter == 1)
-      return Log_event::EVENT_SKIP_COUNT;
-    else
-      return Log_event::shall_skip(rli);
-  }
+User_var_log_event::do_shall_skip(RELAY_LOG_INFO *rli)
+{
+  /*
+    It is a common error to set the slave skip counter to 1 instead
+    of 2 when recovering from an insert which used a auto increment,
+    rand, or user var.  Therefore, if the slave skip counter is 1, we
+    just say that this event should be skipped by ignoring it, meaning
+    that we do not change the value of the slave skip counter since it
+    will be decreased by the following insert event.
+  */
+  if (rli->slave_skip_counter == 1)
+    return Log_event::EVENT_SKIP_IGNORE;
+  else
+    return Log_event::do_shall_skip(rli);
+}
 #endif /* !MYSQL_CLIENT */
 
 
@@ -5920,7 +5931,7 @@ int Rows_log_event::do_apply_event(RELAY_LOG_INFO const *rli)
       default:
 	slave_print_msg(ERROR_LEVEL, rli, thd->net.last_errno,
                         "Error in %s event: row application failed",
-                        get_type_str(), error);
+                        get_type_str());
 	thd->query_error= 1;
 	break;
       }

sql/rpl_rli.cc

@@ -29,7 +29,8 @@ int init_strvar_from_file(char *var, int max_size, IO_CACHE *f,
 
 
 st_relay_log_info::st_relay_log_info()
-  :no_storage(FALSE), info_fd(-1), cur_log_fd(-1), save_temporary_tables(0),
+  :no_storage(FALSE), replicate_same_server_id(::replicate_same_server_id),
+   info_fd(-1), cur_log_fd(-1), save_temporary_tables(0),
    cur_log_old_open_count(0), group_master_log_pos(0), log_space_total(0),
    ignore_log_space_limit(0), last_master_timestamp(0), slave_skip_counter(0),
    abort_pos_wait(0), slave_run_id(0), sql_thd(0), last_slave_errno(0),

sql/rpl_rli.h

@@ -57,6 +57,15 @@ typedef struct st_relay_log_info
   */
   bool no_storage;
 
+  /*
+    If true, events with the same server id should be replicated. This
+    field is set on creation of a relay log info structure by copying
+    the value of ::replicate_same_server_id and can be overridden if
+    necessary. For example of when this is done, check sql_binlog.cc,
+    where the BINLOG statement can be used to execute "raw" events.
+   */
+  bool replicate_same_server_id;
+
   /*** The following variables can only be read when protect by data lock ****/
 
   /*

sql/slave.cc

@@ -811,7 +811,7 @@ do not trust column Seconds_Behind_Master of SHOW SLAVE STATUS");
   {
     if ((master_row= mysql_fetch_row(master_res)) &&
         (::server_id == strtoul(master_row[1], 0, 10)) &&
-        !replicate_same_server_id)
+        !mi->rli.replicate_same_server_id)
       errmsg= "The slave I/O thread stops because master and slave have equal \
 MySQL server ids; these ids must be different for replication to work (or \
 the --replicate-same-server-id option must be used on slave but this does \
@@ -1721,20 +1721,9 @@ static int exec_relay_log_event(THD* thd, RELAY_LOG_INFO* rli)
   if (ev)
   {
     int type_code = ev->get_type_code();
-    int exec_res;
+    int exec_res= 0;
 
     /*
-      Queries originating from this server must be skipped.
-      Low-level events (Format_desc, Rotate, Stop) from this server
-      must also be skipped. But for those we don't want to modify
-      group_master_log_pos, because these events did not exist on the master.
-      Format_desc is not completely skipped.
-      Skip queries specified by the user in slave_skip_counter.
-      We can't however skip events that has something to do with the
-      log files themselves.
-      Filtering on own server id is extremely important, to ignore execution of
-      events created by the creation/rotation of the relay log (remember that
-      now the relay log starts with its Format_desc, has a Rotate etc).
     */
 
     DBUG_PRINT("info",("type_code=%d (%s), server_id=%d",
@@ -1742,8 +1731,27 @@ static int exec_relay_log_event(THD* thd, RELAY_LOG_INFO* rli)
 
 
     /*
-      Execute the event, but first we set some data that is needed for
+      Execute the event to change the database and update the binary
+      log coordinates, but first we set some data that is needed for
       the thread.
+
+      The event will be executed unless it is supposed to be skipped.
+
+      Queries originating from this server must be skipped.  Low-level
+      events (Format_description_log_event, Rotate_log_event,
+      Stop_log_event) from this server must also be skipped. But for
+      those we don't want to modify 'group_master_log_pos', because
+      these events did not exist on the master.
+      Format_description_log_event is not completely skipped.
+
+      Skip queries specified by the user in 'slave_skip_counter'.  We
+      can't however skip events that has something to do with the log
+      files themselves.
+
+      Filtering on own server id is extremely important, to ignore
+      execution of events created by the creation/rotation of the relay
+      log (remember that now the relay log starts with its Format_desc,
+      has a Rotate etc).
     */
 
     thd->server_id = ev->server_id; // use the original server id for logging
@@ -1753,9 +1761,62 @@ static int exec_relay_log_event(THD* thd, RELAY_LOG_INFO* rli)
       ev->when = time(NULL);
     ev->thd = thd; // because up to this point, ev->thd == 0
 
-    exec_res= ev->exec_event(rli);
-    DBUG_PRINT("info", ("exec_event result = %d", exec_res));
-    DBUG_ASSERT(rli->sql_thd==thd);
+    int reason= ev->shall_skip(rli);
+    if (reason == Log_event::EVENT_SKIP_COUNT)
+      --rli->slave_skip_counter;
+    pthread_mutex_unlock(&rli->data_lock);
+    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]));
+    }
+#endif
+
+    DBUG_PRINT("info", ("apply_event error = %d", exec_res));
+    if (exec_res == 0)
+    {
+      int error= ev->update_pos(rli);
+      char buf[22];
+      DBUG_PRINT("info", ("update_pos error = %d", error));
+      DBUG_PRINT("info", ("group %s %s",
+                          llstr(rli->group_relay_log_pos, buf),
+                          rli->group_relay_log_name));
+      DBUG_PRINT("info", ("event %s %s",
+                          llstr(rli->event_relay_log_pos, buf),
+                          rli->event_relay_log_name));
+      /*
+        The update should not fail, so print an error message and
+        return an error code.
+
+        TODO: Replace this with a decent error message when merged
+        with BUG#24954 (which adds several new error message).
+      */
+      if (error)
+      {
+        slave_print_msg(ERROR_LEVEL, rli, ER_UNKNOWN_ERROR,
+                        "It was not possible to update the positions"
+                        " of the relay log information: the slave may"
+                        " be in an inconsistent state."
+                        " Stopped in %s position %s",
+                        rli->group_relay_log_name,
+                        llstr(rli->group_relay_log_pos, buf));
+        DBUG_RETURN(1);
+      }
+    }
+
     /*
        Format_description_log_event should not be deleted because it will be
        used to read info about the relay log's format; it will be deleted when
@@ -2902,7 +2963,7 @@ int queue_event(MASTER_INFO* mi,const char* buf, ulong event_len)
   pthread_mutex_lock(log_lock);
 
   if ((uint4korr(buf + SERVER_ID_OFFSET) == ::server_id) &&
-      !replicate_same_server_id)
+      !mi->rli.replicate_same_server_id)
   {
     /*
       Do not write it to the relay log.

sql/sql_binlog.cc

@@ -150,9 +150,17 @@ void mysql_client_binlog_statement(THD* thd)
       DBUG_PRINT("info", ("bytes_decoded=%d; bufptr=0x%lx; buf[EVENT_LEN_OFFSET]=%u",
                           bytes_decoded, bufptr, uint4korr(bufptr+EVENT_LEN_OFFSET)));
       ev->thd= thd;
-      if (int err= ev->exec_event(thd->rli_fake))
+      /*
+        We go directly to the application phase, since we don't need
+        to check if the event shall be skipped or not.
+
+        Neither do we have to update the log positions, since that is
+        not used at all: the rli_fake instance is used only for error
+        reporting.
+       */
+      if (int err= ev->apply_event(thd->rli_fake))
       {
-        DBUG_PRINT("info", ("exec_event() - error=%d", error));
+        DBUG_PRINT("info", ("apply_event() - error=%d", error));
         /*
           TODO: Maybe a better error message since the BINLOG statement
           now contains several events.