BUG#21304682: VALGRIND ERRORS IN DEBUG PRINTOUTS FOR REPLICATION CODE

Two places in replication code were causing Valgrind errors:

 1. Memory leak in Relay_log_info::wait_for_gtid_set, since it passed
    the return value from Gtid_set::to_string() directly to
    DBUG_PRINT, without storing it anywhere so that it can be freed.

 2. In MYSQL_BIN_LOG::init_gtid_sets would pass a bad pointer to
    DBUG_PRINT in some cases.

In problem #1, an underlying problem was that to_string returns newly
allocated memory and this was easy to miss when reading the code that
calls the function.  It would be better to return the value through a
parameter, since that forces the caller to store it in a variable, and
then it is more obvious that the value must be freed.  And in fact
such a function existed already, so we fix the problem by removing the
(redundant) no-args version of Gtid_set::to_string and using the one-
or two-argument function instead.

In problem #2, print an empty string if we detect that the pointer
will be bad.

These bugs were found when adding some debug printouts to
read_gtids_from_binlog.  These debug printouts never made it to the
server code through any other bug report, but would be useful to have
for future debugging, so including them in this patch.

Additionally, removed the call to global_sid_lock->rdlock() used
before Previous_gtids_log_event::get_str().  This is not needed since
Previous_gtids_log_event doesn't use shared resources.

Author: Sven Sandberg

sql/binlog.cc

@@ -3895,6 +3895,21 @@ read_gtids_from_binlog(const char *filename, Gtid_set *all_gtids,
   mysql_file_close(file, MYF(MY_WME));
   end_io_cache(&log);
 
+  if (all_gtids)
+    all_gtids->dbug_print("all_gtids");
+  else
+    DBUG_PRINT("info", ("all_gtids==NULL"));
+  if (prev_gtids)
+    prev_gtids->dbug_print("prev_gtids");
+  else
+    DBUG_PRINT("info", ("prev_gtids==NULL"));
+  if (first_gtid == NULL)
+    DBUG_PRINT("info", ("first_gtid==NULL"));
+  else if (first_gtid->sidno == 0)
+    DBUG_PRINT("info", ("first_gtid.sidno==0"));
+  else
+    first_gtid->dbug_print(sid_map, "first_gtid");
+
   DBUG_PRINT("info", ("returning %d", ret));
   DBUG_RETURN(ret);
 }
@@ -4019,8 +4034,9 @@ bool MYSQL_BIN_LOG::init_gtid_sets(Gtid_set *all_gtids, Gtid_set *lost_gtids,
                                    bool is_server_starting)
 {
   DBUG_ENTER("MYSQL_BIN_LOG::init_gtid_sets");
-  DBUG_PRINT("info", ("lost_gtids=%p; so we are recovering a %s log",
-                      lost_gtids, lost_gtids == NULL ? "relay" : "binary"));
+  DBUG_PRINT("info", ("lost_gtids=%p; so we are recovering a %s log; is_relay_log=%d",
+                      lost_gtids, lost_gtids == NULL ? "relay" : "binary",
+                      is_relay_log));
 
   /*
     If this is a relay log, we must have the IO thread Master_info trx_parser
@@ -4108,7 +4124,8 @@ bool MYSQL_BIN_LOG::init_gtid_sets(Gtid_set *all_gtids, Gtid_set *lost_gtids,
     bool can_stop_reading= false;
     reached_first_file= (rit == filename_list.rend());
     DBUG_PRINT("info", ("filename='%s' reached_first_file=%d",
-                        reached_first_file ? "" : rit->c_str(), reached_first_file));
+                        reached_first_file ? "" : rit->c_str(),
+                        reached_first_file));
     while (!can_stop_reading && !reached_first_file)
     {
       const char *filename= rit->c_str();

sql/log_event.cc

@@ -13118,9 +13118,7 @@ Previous_gtids_log_event::Previous_gtids_log_event(const Gtid_set *set)
 int Previous_gtids_log_event::pack_info(Protocol *protocol)
 {
   size_t length= 0;
-  global_sid_lock->rdlock();
   char *str= get_str(&length, &Gtid_set::default_string_format);
-  global_sid_lock->unlock();
   if (str == NULL)
     return 1;
   protocol->store(str, length, &my_charset_bin);
@@ -13134,10 +13132,7 @@ void Previous_gtids_log_event::print(FILE *file,
                                      PRINT_EVENT_INFO *print_event_info)
 {
   IO_CACHE *const head= &print_event_info->head_cache;
-
-  global_sid_lock->rdlock();
   char *str= get_str(NULL, &Gtid_set::commented_string_format);
-  global_sid_lock->unlock();
   if (str != NULL)
   {
     if (!print_event_info->short_form)
@@ -13167,7 +13162,7 @@ int Previous_gtids_log_event::add_to_set(Gtid_set *target) const
 char *Previous_gtids_log_event::get_str(
   size_t *length_p, const Gtid_set::String_format *string_format) const
 {
-  DBUG_ENTER("Previous_gtids_log_event::get_str(size_t *)");
+  DBUG_ENTER("Previous_gtids_log_event::get_str(size_t *, const Gtid_set::String_format *)");
   Sid_map sid_map(NULL);
   Gtid_set set(&sid_map, NULL);
   DBUG_PRINT("info", ("temp_buf=%p buf=%p", temp_buf, buf));
@@ -13180,7 +13175,7 @@ char *Previous_gtids_log_event::get_str(
                                length + 1, MYF(MY_WME));
   if (str != NULL)
   {
-    set.to_string(str, string_format);
+    set.to_string(str, false/*need_lock*/, string_format);
     if (length_p != NULL)
       *length_p= length;
   }

sql/mysqld.cc

@@ -4703,6 +4703,9 @@ int mysqld_main(int argc, char **argv)
 
     global_sid_lock->wrlock();
 
+    purged_gtids_from_binlog.dbug_print("purged_gtids_from_binlog");
+    gtids_in_binlog.dbug_print("gtids_in_binlog");
+
     if (!gtids_in_binlog.is_empty() &&
         !gtids_in_binlog.is_subset(executed_gtids))
     {

sql/rpl_group_replication.cc

@@ -333,7 +333,9 @@ char* encoded_gtid_set_to_string(uchar *encoded_gtid_set,
       RETURN_STATUS_OK)
     return NULL;
 
-  return set.to_string();
+  char *buf;
+  set.to_string(&buf);
+  return buf;
 }
 #endif
 

sql/rpl_gtid.h

@@ -1338,39 +1338,6 @@ class Gtid_set
     Gtid_set, false otherwise.
   */
   static bool is_valid(const char *text);
-  /**
-    Return a newly allocated string containing this Gtid_set, or NULL
-    on out of memory.
-  */
-  char *to_string() const
-  {
-    char *str= (char *)my_malloc(key_memory_Gtid_set_to_string,
-                                 get_string_length() + 1, MYF(MY_WME));
-    if (str != NULL)
-      to_string(str);
-    return str;
-  }
-#ifndef DBUG_OFF
-  /// Debug only: Print this Gtid_set to stdout.
-  void print() const
-  {
-    char *str= to_string();
-    printf("%s\n", str);
-    my_free(str);
-  }
-#endif
-  /**
-    Print this Gtid_set to the trace file if debug is enabled; no-op
-    otherwise.
-  */
-  void dbug_print(const char *text= "") const
-  {
-#ifndef DBUG_OFF
-    char *str= to_string();
-    DBUG_PRINT("info", ("%s%s'%s'", text, *text ? ": " : "", str));
-    my_free(str);
-#endif
-  }
 
   /**
     Class Gtid_set::String_format defines the separators used by
@@ -1417,20 +1384,58 @@ class Gtid_set
 
     @param[out] buf Pointer to the buffer where the string should be
     stored. This should have size at least get_string_length()+1.
+    @param need_lock If this Gtid_set has a sid_lock, then the write
+    lock must be held while generating the string. If this parameter
+    is true, then this function acquires and releases the lock;
+    otherwise it asserts that the caller holds the lock.
     @param string_format String_format object that specifies
     separators in the resulting text.
     @return Length of the generated string.
   */
-  int to_string(char *buf, const String_format *string_format= NULL) const;
+  int to_string(char *buf, bool need_lock= false,
+                const String_format *string_format= NULL) const;
 
   /**
     Formats a Gtid_set as a string and saves in a newly allocated buffer.
     @param[out] buf Pointer to pointer to string. The function will
     set it to point to the newly allocated buffer, or NULL on out of memory.
+    @param need_lock If this Gtid_set has a sid_lock, then the write
+    lock must be held while generating the string. If this parameter
+    is true, then this function acquires and releases the lock;
+    otherwise it asserts that the caller holds the lock.
     @param string_format Specifies how to format the string.
     @retval Length of the generated string, or -1 on out of memory.
   */
-  int to_string(char **buf, const String_format *string_format= NULL) const;
+  int to_string(char **buf, bool need_lock= false,
+                const String_format *string_format= NULL) const;
+#ifndef DBUG_OFF
+  /// Debug only: Print this Gtid_set to stdout.
+  void print(bool need_lock= false,
+             const Gtid_set::String_format *sf= NULL) const
+  {
+    char *str;
+    to_string(&str, need_lock, sf);
+    printf("%s\n", str ? str : "out of memory in Gtid_set::print");
+    my_free(str);
+  }
+#endif
+  /**
+    Print this Gtid_set to the trace file if debug is enabled; no-op
+    otherwise.
+  */
+  void dbug_print(const char *text= "", bool need_lock= false,
+                  const Gtid_set::String_format *sf= NULL) const
+  {
+#ifndef DBUG_OFF
+    char *str;
+    to_string(&str, need_lock, sf);
+    DBUG_PRINT("info", ("%s%s'%s'",
+                        text,
+                        *text ? ": " : "",
+                        str ? str : "out of memory in Gtid_set::dbug_print"));
+    my_free(str);
+#endif
+  }
   /**
     Gets all gtid intervals from this Gtid_set.
 

sql/rpl_gtid_set.cc

@@ -829,30 +829,48 @@ rpl_gno Gtid_set::get_last_gno(rpl_sidno sidno) const
   DBUG_RETURN(gno);
 }
 
-int Gtid_set::to_string(char **buf_arg, const Gtid_set::String_format *sf_arg) const
+int Gtid_set::to_string(char **buf_arg, bool need_lock,
+                        const Gtid_set::String_format *sf_arg) const
 {
   DBUG_ENTER("Gtid_set::to_string");
+  if (sid_lock != NULL)
+  {
+    if (need_lock)
+      sid_lock->wrlock();
+    else
+      sid_lock->assert_some_wrlock();
+  }
   int len= get_string_length(sf_arg);
   *buf_arg= (char *)my_malloc(key_memory_Gtid_set_to_string,
                               len + 1, MYF(MY_WME));
   if (*buf_arg == NULL)
     DBUG_RETURN(-1);
-  to_string(*buf_arg, sf_arg);
+  to_string(*buf_arg, false/*need_lock*/, sf_arg);
+  if (sid_lock != NULL && need_lock)
+    sid_lock->unlock();
   DBUG_RETURN(len);
 }
 
-int Gtid_set::to_string(char *buf, const Gtid_set::String_format *sf) const
+int Gtid_set::to_string(char *buf, bool need_lock,
+                        const Gtid_set::String_format *sf) const
 {
   DBUG_ENTER("Gtid_set::to_string");
   DBUG_ASSERT(sid_map != NULL);
   if (sid_lock != NULL)
-    sid_lock->assert_some_wrlock();
+  {
+    if (need_lock)
+      sid_lock->wrlock();
+    else
+      sid_lock->assert_some_wrlock();
+  }
   if (sf == NULL)
     sf= &default_string_format;
   if (sf->empty_set_string != NULL && is_empty())
   {
     memcpy(buf, sf->empty_set_string, sf->empty_set_string_length);
     buf[sf->empty_set_string_length]= '\0';
+    if (sid_lock != NULL && need_lock)
+      sid_lock->unlock();
     DBUG_RETURN(sf->empty_set_string_length);
   } 
   rpl_sidno map_max_sidno= sid_map->get_max_sidno();
@@ -907,6 +925,8 @@ int Gtid_set::to_string(char *buf, const Gtid_set::String_format *sf) const
   DBUG_PRINT("info", ("ret='%s' strlen(s)=%zu s-buf=%lu get_string_length=%d", buf,
              strlen(buf), (ulong) (s - buf), get_string_length(sf)));
   DBUG_ASSERT(s - buf == get_string_length(sf));
+  if (sid_lock != NULL && need_lock)
+    sid_lock->unlock();
   DBUG_RETURN((int)(s - buf));
 }
 

sql/rpl_master.cc

@@ -386,7 +386,7 @@ bool com_binlog_dump_gtid(THD *thd, char *packet, size_t packet_length)
   if (slave_gtid_executed.add_gtid_encoding(packet_position, data_size) !=
       RETURN_STATUS_OK)
     DBUG_RETURN(true);
-  gtid_string= slave_gtid_executed.to_string();
+  slave_gtid_executed.to_string(&gtid_string);
   DBUG_PRINT("info", ("Slave %d requested to read %s at position %llu gtid set "
                       "'%s'.", thd->server_id, name, pos, gtid_string));
 

sql/rpl_rli.cc

@@ -955,10 +955,14 @@ int Relay_log_info::wait_for_gtid_set(THD* thd, const Gtid_set* wait_gtid_set,
     const Gtid_set* executed_gtids= gtid_state->get_executed_gtids();
     const Owned_gtids* owned_gtids= gtid_state->get_owned_gtids();
 
+    char *wait_gtid_set_buf;
+    wait_gtid_set->to_string(&wait_gtid_set_buf);
     DBUG_PRINT("info", ("Waiting for '%s'. is_subset: %d and "
                         "!is_intersection_nonempty: %d",
-      wait_gtid_set->to_string(), wait_gtid_set->is_subset(executed_gtids),
-      !owned_gtids->is_intersection_nonempty(wait_gtid_set)));
+                        wait_gtid_set_buf,
+                        wait_gtid_set->is_subset(executed_gtids),
+                        !owned_gtids->is_intersection_nonempty(wait_gtid_set)));
+    my_free(wait_gtid_set_buf);
     executed_gtids->dbug_print("gtid_executed:");
     owned_gtids->dbug_print("owned_gtids:");
 
@@ -1446,7 +1450,8 @@ bool Relay_log_info::is_until_satisfied(THD *thd, Log_event *ev)
       const Gtid_set* executed_gtids= gtid_state->get_executed_gtids();
       if (until_sql_gtids.is_intersection_nonempty(executed_gtids))
       {
-        char *buffer= until_sql_gtids.to_string();
+        char *buffer;
+        until_sql_gtids.to_string(&buffer);
         global_sid_lock->unlock();
         sql_print_information("Slave SQL thread stopped because "
                               "UNTIL SQL_BEFORE_GTIDS %s is already "
@@ -1462,7 +1467,8 @@ bool Relay_log_info::is_until_satisfied(THD *thd, Log_event *ev)
       global_sid_lock->rdlock();
       if (until_sql_gtids.contains_gtid(gev->get_sidno(false), gev->get_gno()))
       {
-        char *buffer= until_sql_gtids.to_string();
+        char *buffer;
+        until_sql_gtids.to_string(&buffer);
         global_sid_lock->unlock();
         sql_print_information("Slave SQL thread stopped because it reached "
                               "UNTIL SQL_BEFORE_GTIDS %s", buffer);
@@ -1480,7 +1486,8 @@ bool Relay_log_info::is_until_satisfied(THD *thd, Log_event *ev)
       const Gtid_set* executed_gtids= gtid_state->get_executed_gtids();
       if (until_sql_gtids.is_subset(executed_gtids))
       {
-        char *buffer= until_sql_gtids.to_string();
+        char *buffer;
+        until_sql_gtids.to_string(&buffer);
         global_sid_lock->unlock();
         sql_print_information("Slave SQL thread stopped because it reached "
                               "UNTIL SQL_AFTER_GTIDS %s", buffer);

sql/sys_vars.cc

@@ -5179,10 +5179,10 @@ bool Sys_var_gtid_purged::global_update(THD *thd, set_var *var)
   bool error= false;
 
   global_sid_lock->wrlock();
-  char *previous_gtid_executed= gtid_state->get_executed_gtids()->to_string();
-  char *previous_gtid_lost= gtid_state->get_lost_gtids()->to_string();
-  char *current_gtid_executed= NULL;
-  char *current_gtid_lost= NULL;
+  char *previous_gtid_executed= NULL, *previous_gtid_purged= NULL,
+    *current_gtid_executed= NULL, *current_gtid_purged= NULL;
+  gtid_state->get_executed_gtids()->to_string(&previous_gtid_executed);
+  gtid_state->get_lost_gtids()->to_string(&previous_gtid_purged);
   enum_return_status ret;
   Gtid_set gtid_set(global_sid_map, var->save_result.string_value.str,
                     &ret, global_sid_lock);
@@ -5199,21 +5199,21 @@ bool Sys_var_gtid_purged::global_update(THD *thd, set_var *var)
     error= true;
     goto end;
   }
-  current_gtid_executed= gtid_state->get_executed_gtids()->to_string();
-  current_gtid_lost= gtid_state->get_lost_gtids()->to_string();
+  gtid_state->get_executed_gtids()->to_string(&current_gtid_executed);
+  gtid_state->get_lost_gtids()->to_string(&current_gtid_purged);
   global_sid_lock->unlock();
 
   // Log messages saying that GTID_PURGED and GTID_EXECUTED were changed.
   sql_print_information(ER(ER_GTID_PURGED_WAS_CHANGED),
-                        previous_gtid_lost, current_gtid_lost);
+                        previous_gtid_purged, current_gtid_purged);
   sql_print_information(ER(ER_GTID_EXECUTED_WAS_CHANGED),
                         previous_gtid_executed, current_gtid_executed);
 
 end:
   my_free(previous_gtid_executed);
-  my_free(previous_gtid_lost);
+  my_free(previous_gtid_purged);
   my_free(current_gtid_executed);
-  my_free(current_gtid_lost);
+  my_free(current_gtid_purged);
   DBUG_RETURN(error);
 #else
   DBUG_RETURN(true);