List:Commits« Previous MessageNext Message »
From:Alfranio Correia Date:July 12 2009 11:24pm
Subject:bzr commit into mysql-5.1-bugteam branch (alfranio.correia:3013)
Bug#45292
View as plain text  
#At file:///home/acorreia/workspace.sun/repository.mysql/bzrwork/bug-45292/mysql-5.1-bugteam/ based on revid:joro@stripped

 3013 Alfranio Correia	2009-07-13
      BUG#45292 orphan binary log created when starting server twice
      
      This patch fixes two bugs as follows. First, aborting the server while purging
      binary logs might generate orphan files due to how the purge operation was
      implemented:
      
            (purge routine - sql/log.cc - MYSQL_BIN_LOG::purge_logs)
      
        1 - register the files to be removed in a temporary buffer.
        2 - update the log-bin.index.
        3 - flush the log-bin.index.
        4 - erase the files whose names where register in the temporary buffer
        in step 1.
      
      Thus aborting a server while  executing step 4 would generate an orphan file.
      To fix this issue, we record the files to be purged before removing them from
      the index file and from the file system. So if a failure happens such registers
      can be used to automatically remove dangling files. The new steps might be
      outlined as follows:
      
            (purge routine - sql/log.cc - MYSQL_BIN_LOG::purge_logs)
      
        1 - register the files to be removed in a the log-bin.purge
        place in the data directory.
        2 - update the log-bin.index.
        3 - flush the log-bin.index.
        4 - erase the files whose names where register in the log-bin.purge
        in step 1.
      
            (purge routine - sql/log.cc - MYSQL_BIN_LOG::open_index_file)
      
        1 - open the log-bin.index.
        2 - open the log-bin.purge.
        3 - for each file in log-bin.purge
          3.1 Check if file is in log-bin.index and if so ignored it.
          3.2 Otherwise, delete it.
      
      Regarding the second issue. The purge operation was allowing to remove a file
      in use thus leading to the loss of data and possible inconsistencies between
      the master and slave. Roughly, there was a problem with the sql_repl.cc::bool
      log_in_use(), which was not correctly checking if a file was in use. To avoid
      this issue, we replaced the call to such function by a call to the method
      MYSQL_BIN_LOG::is_active() and remove the previous function as it was obsolete.

    modified:
      mysql-test/suite/binlog/r/binlog_index.result
      mysql-test/suite/binlog/t/binlog_index.test
      mysql-test/suite/rpl_ndb/r/rpl_ndb_row_001.result
      sql/log.cc
      sql/log.h
      sql/sql_repl.cc
      sql/sql_repl.h
=== modified file 'mysql-test/suite/binlog/r/binlog_index.result'
--- a/mysql-test/suite/binlog/r/binlog_index.result	2009-01-23 12:22:05 +0000
+++ b/mysql-test/suite/binlog/r/binlog_index.result	2009-07-12 23:24:45 +0000
@@ -1,3 +1,4 @@
+call mtr.add_suppression('Attempting backtrace');
 flush logs;
 flush logs;
 flush logs;
@@ -37,4 +38,16 @@ Level	Code	Message
 Error	1377	a problem with deleting master-bin.000001; consider examining correspondence of your binlog index file to the actual binlog files
 Error	1377	Fatal error during log purge
 reset master;
+flush logs;
+SET SESSION debug="+d,crash_before_update_index";
+purge binary logs TO 'master-bin.000002';
+ERROR HY000: Lost connection to MySQL server during query
+flush logs;
+SET SESSION debug="+d,crash_non_critical_after_update_index";
+purge binary logs TO 'master-bin.000004';
+ERROR HY000: Lost connection to MySQL server during query
+flush logs;
+SET SESSION debug="+d,crash_critical_after_update_index";
+purge binary logs TO 'master-bin.000006';
+ERROR HY000: Lost connection to MySQL server during query
 End of tests

=== modified file 'mysql-test/suite/binlog/t/binlog_index.test'
--- a/mysql-test/suite/binlog/t/binlog_index.test	2008-04-05 11:09:53 +0000
+++ b/mysql-test/suite/binlog/t/binlog_index.test	2009-07-12 23:24:45 +0000
@@ -3,6 +3,7 @@
 #
 source include/have_log_bin.inc;
 source include/not_embedded.inc;
+call mtr.add_suppression('Attempting backtrace');
 
 #
 # testing purge binary logs TO
@@ -66,4 +67,35 @@ rmdir $MYSQLD_DATADIR/master-bin.000001;
 --disable_warnings
 reset master;
 --enable_warnings
+
+flush logs;
+
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_before_update_index";
+--error 2013
+purge binary logs TO 'master-bin.000002';
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+flush logs;
+
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_non_critical_after_update_index";
+--error 2013
+purge binary logs TO 'master-bin.000004';
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+flush logs;
+
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_critical_after_update_index";
+--error 2013
+purge binary logs TO 'master-bin.000006';
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
 --echo End of tests

=== modified file 'mysql-test/suite/rpl_ndb/r/rpl_ndb_row_001.result'
--- a/mysql-test/suite/rpl_ndb/r/rpl_ndb_row_001.result	2007-12-19 08:42:31 +0000
+++ b/mysql-test/suite/rpl_ndb/r/rpl_ndb_row_001.result	2009-07-12 23:24:45 +0000
@@ -42,6 +42,8 @@ COUNT(*)
 5000
 LOCK TABLES t1 READ;
 START SLAVE;
+Warnings:
+Error	1100	Table 'ndb_binlog_index' was not locked with LOCK TABLES
 UNLOCK TABLES;
 SELECT COUNT(*) FROM t1;
 COUNT(*)

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2009-06-19 08:24:43 +0000
+++ b/sql/log.cc	2009-07-12 23:24:45 +0000
@@ -2388,8 +2388,9 @@ MYSQL_BIN_LOG::MYSQL_BIN_LOG()
     before main().
   */
   index_file_name[0] = 0;
+  purge_file_name[0] = 0;
   bzero((char*) &index_file, sizeof(index_file));
-  bzero((char*) &purge_temp, sizeof(purge_temp));
+  bzero((char*) &purge_file, sizeof(purge_file));
 }
 
 /* this is called only once */
@@ -2469,10 +2470,20 @@ bool MYSQL_BIN_LOG::open_index_file(cons
       my_close(index_file_nr,MYF(0));
     return TRUE;
   }
+
+  #ifdef HAVE_REPLICATION
+  /* Read each entry from purge_file and delete the file. */
+  if (open_purge_file(index_file_name_arg) || process_purge_file(NULL, NULL, TRUE))
+  {
+    sql_print_error("MYSQL_BIN_LOG::open_index_file to process cache to "
+                    "purge logs.");
+    return TRUE;
+  }
+  #endif
+
   return FALSE;
 }
 
-
 /**
   Open a (new) binlog file.
 
@@ -3134,28 +3145,12 @@ int MYSQL_BIN_LOG::purge_logs(const char
     goto err;
   }
 
-  /*
-    For crash recovery reasons the index needs to be updated before
-    any files are deleted. Move files to be deleted into a temp file
-    to be processed after the index is updated.
-  */
-  if (!my_b_inited(&purge_temp))
+  if ((error= open_purge_file(NULL)) ||
+       DBUG_EVALUATE_IF("fault_injection_open_info_purge", 1, 0))
   {
-    if ((error=open_cached_file(&purge_temp, mysql_tmpdir, TEMP_PREFIX,
-                                DISK_BUFFER_SIZE, MYF(MY_WME))))
-    {
-      sql_print_error("MYSQL_LOG::purge_logs failed to open purge_temp");
-      goto err;
-    }
-  }
-  else
-  {
-    if ((error=reinit_io_cache(&purge_temp, WRITE_CACHE, 0, 0, 1)))
-    {
-      sql_print_error("MYSQL_LOG::purge_logs failed to reinit purge_temp "
-                      "for write");
-      goto err;
-    }
+    sql_print_error("MSYQL_LOG::purge_logs failed to prepare cache to "
+                    "purge logs.");
+    goto err;
   }
 
   /*
@@ -3165,20 +3160,32 @@ int MYSQL_BIN_LOG::purge_logs(const char
   if ((error=find_log_pos(&log_info, NullS, 0 /*no mutex*/)))
     goto err;
   while ((strcmp(to_log,log_info.log_file_name) || (exit_loop=included)) &&
-         !log_in_use(log_info.log_file_name))
+         !is_active(log_info.log_file_name))
   {
-    if ((error=my_b_write(&purge_temp, (const uchar*)log_info.log_file_name,
+    if ((error=my_b_write(&purge_file, (const uchar*)log_info.log_file_name,
                           strlen(log_info.log_file_name))) ||
-        (error=my_b_write(&purge_temp, (const uchar*)"\n", 1)))
+        (error=my_b_write(&purge_file, (const uchar*)"\n", 1)))
     {
-      sql_print_error("MYSQL_LOG::purge_logs failed to copy %s to purge_temp",
+      sql_print_error("MYSQL_LOG::purge_logs failed to copy %s to purge_file",
                       log_info.log_file_name);
       goto err;
     }
 
     if (find_next_log(&log_info, 0) || exit_loop)
       break;
- }
+  }
+
+  DBUG_EXECUTE_IF("crash_before_update_index", abort(););
+
+  if ((error= flush_io_cache(&purge_file)) ||
+      (error= my_sync(purge_file.file, MYF(MY_WME))))
+  {
+    sql_print_error("MSYQL_LOG::purge_logs failed to flush cache to purge "
+                    "logs.");
+    goto err;
+  }
+
+  DBUG_EXECUTE_IF("crash_critical_after_update_index", abort(););
 
   /* We know how many files to delete. Update index file. */
   if ((error=update_log_index(&log_info, need_update_threads)))
@@ -3187,29 +3194,93 @@ int MYSQL_BIN_LOG::purge_logs(const char
     goto err;
   }
 
-  DBUG_EXECUTE_IF("crash_after_update_index", abort(););
+  DBUG_EXECUTE_IF("crash_non_critical_after_update_index", abort(););
+
+  /* Read each entry from purge_file and delete the file. */
+  if ((error= process_purge_file(thd, decrease_log_space, FALSE))) 
+  {
+    sql_print_error("MSYQL_LOG::purge_logs failed to process cache to "
+                    "purge logs.");
+  }
+
+err:
+  if (need_mutex)
+    pthread_mutex_unlock(&LOCK_index);
+  DBUG_RETURN(error);
+}
+
+  /*
+    For crash recovery reasons the index needs to be updated before
+    any files are deleted. Move files to be deleted into a temp file
+    to be processed after the index is updated.
+  */
+int MYSQL_BIN_LOG::open_purge_file(const char *base_file_name)
+{
+  int error= 0;
+  File file;
+
+  DBUG_ENTER("MYSQL_BIN_LOG::open_info_purge"); 
+  if (!my_b_inited(&purge_file))
+  {
+    if (fn_format(purge_file_name, base_file_name, mysql_data_home,
+                  ".purge", MYF(MY_UNPACK_FILENAME | MY_SAFE_PATH |
+                                MY_REPLACE_EXT)) == NULL ||
+        (file= my_open(purge_file_name, O_RDWR | O_CREAT | O_BINARY,
+                       MYF(MY_WME | ME_WAITTANG))) < 0  ||
+        init_io_cache(&purge_file, file, IO_SIZE, READ_CACHE,
+                      0, 0, MYF(MY_WME | MY_NABP | MY_WAIT_IF_FULL)))
+    {
+      error= 1;
+      sql_print_error("MYSQL_LOG::open_info_purge failed to open purge_file.");
+    }
+  }
+  else
+  {
+    if ((error=reinit_io_cache(&purge_file, WRITE_CACHE, 0, 0, 1)))
+    {
+      error= 1;
+      sql_print_error("MYSQL_LOG::open_info_purge failed to reinit purge_file "
+                      "for write.");
+    }
+    file= purge_file.file;
+    if (!error && (my_chsize(file, 0, '\n', MYF(MY_WME)) ||
+      my_sync(file, MYF(MY_WME))))
+    {
+      error= 1;
+      sql_print_error("MYSQL_LOG::open_info_purge failed to clean purge_file.");
+    }
+  }
+  DBUG_RETURN(error);
+}
+
+int MYSQL_BIN_LOG::process_purge_file(THD *thd, ulonglong *decrease_log_space, 
+                                      bool need_mutex)
+{
+  int error= 0;
+  LOG_INFO log_info;
+  LOG_INFO check_log_info;
+  
+  DBUG_ENTER("MYSQL_BIN_LOG::process_purge_file");
 
-  /* Switch purge_temp for read. */
-  if ((error=reinit_io_cache(&purge_temp, READ_CACHE, 0, 0, 0)))
+  if ((error=reinit_io_cache(&purge_file, READ_CACHE, 0, 0, 0)))
   {
-    sql_print_error("MSYQL_LOG::purge_logs failed to reinit purge_temp "
+    sql_print_error("MSYQL_LOG::process_purge_file failed to reinit purge_file "
                     "for read");
     goto err;
   }
 
-  /* Read each entry from purge_temp and delete the file. */
   for (;;)
   {
     uint length;
 
-    if ((length=my_b_gets(&purge_temp, log_info.log_file_name,
+    if ((length=my_b_gets(&purge_file, log_info.log_file_name,
                           FN_REFLEN)) <= 1)
     {
-      if (purge_temp.error)
+      if (purge_file.error)
       {
-        error= purge_temp.error;
-        sql_print_error("MSYQL_LOG::purge_logs error %d reading from "
-                        "purge_temp", error);
+        error= purge_file.error;
+        sql_print_error("MSYQL_LOG::process_purge_file error %d reading from "
+                        "purge_file", error);
         goto err;
       }
 
@@ -3270,64 +3341,63 @@ int MYSQL_BIN_LOG::purge_logs(const char
     }
     else
     {
-      DBUG_PRINT("info",("purging %s",log_info.log_file_name));
-      if (!my_delete(log_info.log_file_name, MYF(0)))
-      {
-        if (decrease_log_space)
-          *decrease_log_space-= s.st_size;
-      }
-      else
+      if (find_log_pos(&check_log_info, log_info.log_file_name, need_mutex))
       {
-        if (my_errno == ENOENT) 
+        DBUG_PRINT("info",("purging %s",log_info.log_file_name));
+        if (!my_delete(log_info.log_file_name, MYF(0)))
         {
-          if (thd)
-          {
-            push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_WARN,
-                                ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE),
-                                log_info.log_file_name);
-          }
-          sql_print_information("Failed to delete file '%s'",
-                                log_info.log_file_name);
-          my_errno= 0;
+          if (decrease_log_space)
+            *decrease_log_space-= s.st_size;
         }
         else
         {
-          if (thd)
+          if (my_errno == ENOENT) 
           {
-            push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_ERROR,
-                                ER_BINLOG_PURGE_FATAL_ERR,
-                                "a problem with deleting %s; "
-                                "consider examining correspondence "
-                                "of your binlog index file "
-                                "to the actual binlog files",
+            if (thd)
+            {
+              push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_WARN,
+                                  ER_LOG_PURGE_NO_FILE, ER(ER_LOG_PURGE_NO_FILE),
+                                  log_info.log_file_name);
+            }
+            sql_print_information("Failed to delete file '%s'",
                                 log_info.log_file_name);
+            my_errno= 0;
           }
           else
           {
-            sql_print_information("Failed to delete file '%s'; "
+            if (thd)
+            {
+              push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_ERROR,
+                                  ER_BINLOG_PURGE_FATAL_ERR,
+                                  "a problem with deleting %s; "
                                   "consider examining correspondence "
                                   "of your binlog index file "
                                   "to the actual binlog files",
                                   log_info.log_file_name);
-          }
-          if (my_errno == EMFILE)
-          {
-            DBUG_PRINT("info",
-                       ("my_errno: %d, set ret = LOG_INFO_EMFILE", my_errno));
-            error= LOG_INFO_EMFILE;
+            }
+            else
+            {
+              sql_print_information("Failed to delete file '%s'; "
+                                    "consider examining correspondence "
+                                    "of your binlog index file "
+                                    "to the actual binlog files",
+                                    log_info.log_file_name);
+            }
+            if (my_errno == EMFILE)
+            {
+              DBUG_PRINT("info",
+                         ("my_errno: %d, set ret = LOG_INFO_EMFILE", my_errno));
+              error= LOG_INFO_EMFILE;
+              goto err;
+            }
+            error= LOG_INFO_FATAL;
             goto err;
           }
-          error= LOG_INFO_FATAL;
-          goto err;
         }
       }
     }
   }
-
 err:
-  close_cached_file(&purge_temp);
-  if (need_mutex)
-    pthread_mutex_unlock(&LOCK_index);
   DBUG_RETURN(error);
 }
 
@@ -3367,7 +3437,7 @@ int MYSQL_BIN_LOG::purge_logs_before_dat
     goto err;
 
   while (strcmp(log_file_name, log_info.log_file_name) &&
-	 !log_in_use(log_info.log_file_name))
+	 !is_active(log_info.log_file_name))
   {
     if (!my_stat(log_info.log_file_name, &stat_area, MYF(0)))
     {
@@ -4663,6 +4733,13 @@ void MYSQL_BIN_LOG::close(uint exiting)
       write_error= 1;
       sql_print_error(ER(ER_ERROR_ON_WRITE), index_file_name, errno);
     }
+
+    end_io_cache(&purge_file);
+    if (my_close(purge_file.file, MYF(0)) < 0 && ! write_error)
+    {
+      write_error= 1;
+      sql_print_error(ER(ER_ERROR_ON_WRITE), purge_file_name, errno);
+    }
   }
   log_state= (exiting & LOG_CLOSE_TO_BE_OPENED) ? LOG_TO_BE_OPENED : LOG_CLOSED;
   safeFree(name);

=== modified file 'sql/log.h'
--- a/sql/log.h	2009-06-18 13:52:46 +0000
+++ b/sql/log.h	2009-07-12 23:24:45 +0000
@@ -234,13 +234,14 @@ class MYSQL_BIN_LOG: public TC_LOG, priv
   ulonglong bytes_written;
   IO_CACHE index_file;
   /*
-    purge_temp is a temp file used in purge_logs so that the index file
+    purge_file is a temp file used in purge_logs so that the index file
     can be updated before deleting files from disk, yielding better crash
     recovery. It is created on demand the first time purge_logs is called
     and then reused for subsequent calls. It is cleaned up in cleanup().
   */
-  IO_CACHE purge_temp;
+  IO_CACHE purge_file;
   char index_file_name[FN_REFLEN];
+  char purge_file_name[FN_REFLEN];
   /*
      The max size before rotation (usable only if log_type == LOG_BIN: binary
      logs and relay logs).
@@ -384,6 +385,9 @@ public:
                  ulonglong *decrease_log_space);
   int purge_logs_before_date(time_t purge_time);
   int purge_first_log(Relay_log_info* rli, bool included);
+  int open_purge_file(const char *base_file_name);
+  int process_purge_file(THD *thd, ulonglong *decrease_log_space,
+                         bool mutex);
   bool reset_logs(THD* thd);
   void close(uint exiting);
 

=== modified file 'sql/sql_repl.cc'
--- a/sql/sql_repl.cc	2009-06-29 14:00:47 +0000
+++ b/sql/sql_repl.cc	2009-07-12 23:24:45 +0000
@@ -202,34 +202,6 @@ void adjust_linfo_offsets(my_off_t purge
   pthread_mutex_unlock(&LOCK_thread_count);
 }
 
-
-bool log_in_use(const char* log_name)
-{
-  size_t log_name_len = strlen(log_name) + 1;
-  THD *tmp;
-  bool result = 0;
-
-  pthread_mutex_lock(&LOCK_thread_count);
-  I_List_iterator<THD> it(threads);
-
-  while ((tmp=it++))
-  {
-    LOG_INFO* linfo;
-    if ((linfo = tmp->current_linfo))
-    {
-      pthread_mutex_lock(&linfo->lock);
-      result = !bcmp((uchar*) log_name, (uchar*) linfo->log_file_name,
-                     log_name_len);
-      pthread_mutex_unlock(&linfo->lock);
-      if (result)
-	break;
-    }
-  }
-
-  pthread_mutex_unlock(&LOCK_thread_count);
-  return result;
-}
-
 bool purge_error_message(THD* thd, int res)
 {
   uint errmsg= 0;

=== modified file 'sql/sql_repl.h'
--- a/sql/sql_repl.h	2008-03-14 17:38:54 +0000
+++ b/sql/sql_repl.h	2009-07-12 23:24:45 +0000
@@ -46,7 +46,6 @@ int reset_slave(THD *thd, Master_info* m
 int reset_master(THD* thd);
 bool purge_master_logs(THD* thd, const char* to_log);
 bool purge_master_logs_before_date(THD* thd, time_t purge_time);
-bool log_in_use(const char* log_name);
 void adjust_linfo_offsets(my_off_t purge_offset);
 bool show_binlogs(THD* thd);
 extern int init_master_info(Master_info* mi);


Attachment: [text/bzr-bundle]
Thread
bzr commit into mysql-5.1-bugteam branch (alfranio.correia:3013)Bug#45292Alfranio Correia13 Jul
  • Re: bzr commit into mysql-5.1-bugteam branch (alfranio.correia:3013)Bug#45292Luís Soares14 Jul
    • Re: bzr commit into mysql-5.1-bugteam branch (alfranio.correia:3013)Bug#45292Alfranio Correia14 Jul
      • Re: bzr commit into mysql-5.1-bugteam branch (alfranio.correia:3013)Bug#45292Luís Soares14 Jul