BUG#38734 rpl_server_id2 sync_with_master failed

Rotate event is automatically generated and written when rotating binary
log or relay log. Rotate events for relay logs are usually ignored by slave
SQL thread becuase they have the same server id as that of the slave.
However, if --replicate-same-server-id is enabled, rotate event
for relay log would be treated as if it's a rotate event from master, and
would be executed by slave to update the rli->group_master_log_name and
rli->group_master_log_pos to a wrong value and cause the MASTER_POS_WAIT
function to fail and return NULL.

This patch fixed this problem by setting a flag bit (LOG_EVENT_RELAY_LOG_F)
in the event to tell the SQL thread to ignore these Rotate events generated
for relay logs.

This patch also added another binlog event flag bit (LOG_EVENT_ARTIFICIAL_F)
to distinquish faked events, the method used before this was by checking if
log_pos was zero.


sql/log.h:
  Add a member to MYSQL_BIN_LOG to distinguish binary log from relay log.
sql/log_event.cc:
  Change artificial_event member to LOG_EVENT_ARTIFICIAL_F flag
  
  If LOG_EVENT_RELAY_LOG_F is set in the event flags for a rotate event, ignore it when updating position
  
  Refactored the code in Rotate_log_event::do_update_pos
sql/log_event.h:
  Add LOG_EVENT_RELAY_LOG_F flag to Log_event flags
  Add RELAY_LOG flag to Rotate_log_event flags
sql/sql_repl.cc:
  Set LOG_EVENT_ARTIFICIAL_F for fake rotate events

6 files changed, 50 insertions, 30 deletions

diff --git a/sql/log.cc b/sql/log.cc
index 49c9bce95f1..f459b4349cb 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -2346,6 +2346,7 @@ const char *MYSQL_LOG::generate_name(const char *log_name,
 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_name,
       */
       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 need_lock)
         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;
     }
diff --git a/sql/log.h b/sql/log.h
index 20a1b7e8e6d..b1a3274b60e 100644
--- a/sql/log.h
+++ b/sql/log.h
@@ -274,6 +274,10 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
 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
diff --git a/sql/log_event.cc b/sql/log_event.cc
index 8527109ca89..b6b1b88e58c 100644
--- a/sql/log_event.cc
+++ b/sql/log_event.cc
@@ -810,9 +810,8 @@ bool Log_event::write_header(IO_CACHE* file, ulong event_data_length)
   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;
   }
@@ -2625,7 +2624,7 @@ Query_log_event::do_shall_skip(Relay_log_info *rli)
 #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);
 }
@@ -2673,7 +2672,7 @@ void Start_log_event_v3::print(FILE* file, PRINT_EVENT_INFO* print_event_info)
       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
     /*
@@ -2715,8 +2714,6 @@ Start_log_event_v3::Start_log_event_v3(const char* buf,
   // 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;
 }
 
@@ -3117,7 +3114,7 @@ int Format_description_log_event::do_apply_event(Relay_log_info const *rli)
     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,
@@ -4054,6 +4051,8 @@ Rotate_log_event::Rotate_log_event(const char* new_log_ident_arg,
 #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
@@ -4125,8 +4124,6 @@ int Rotate_log_event::do_update_pos(Relay_log_info *rli)
   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
@@ -4144,23 +4141,24 @@ int Rotate_log_event::do_update_pos(Relay_log_info *rli)
     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.
@@ -4174,9 +4172,9 @@ int Rotate_log_event::do_update_pos(Relay_log_info *rli)
     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);
 }
diff --git a/sql/log_event.h b/sql/log_event.h
index 041c41dc71b..2ee0bf7e51d 100644
--- a/sql/log_event.h
+++ b/sql/log_event.h
@@ -450,6 +450,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
@@ -966,7 +985,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);
@@ -2065,12 +2087,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.
   */
@@ -2098,7 +2114,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)
@@ -2518,7 +2533,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;
diff --git a/sql/rpl_rli.cc b/sql/rpl_rli.cc
index b6dfd1a1dc8..3a0f784d195 100644
--- a/sql/rpl_rli.cc
+++ b/sql/rpl_rli.cc
@@ -155,6 +155,7 @@ int init_relay_log_info(Relay_log_info* rli,
       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 */
diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc
index 932b7a67b4d..7aa54d3208f 100644
--- a/sql/sql_repl.cc
+++ b/sql/sql_repl.cc
@@ -63,7 +63,7 @@ static int fake_rotate_event(NET* net, String* packet, char* log_file_name,
   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);