BUG#45292 orphan binary log created when starting server twice

This patch fixes three 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 a failure while  executing step 4 would generate an orphan file. Second,
a similar issue might happen while creating a new binary as follows:

          (create routine - sql/log.cc - MYSQL_BIN_LOG::open)

      1 - open the new log-bin.
      2 - update the log-bin.index.

Thus a failure while executing step 1 would generate an orphan file.

To fix these issues, we record the files to be purged or created before really
removing or adding them. So if a failure happens such records 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 the log-bin.~rec~ placed in
      the data directory.
      2 - update the log-bin.index.
      3 - flush the log-bin.index.
      4 - delete the log-bin.~rec~.

          (create routine - sql/log.cc - MYSQL_BIN_LOG::open)

      1 - register the file to be created in the log-bin.~rec~
      placed in the data directory.
      2 - open the new log-bin.
      3 - update the log-bin.index.
      4 - delete the log-bin.~rec~.

          (recovery routine - sql/log.cc - MYSQL_BIN_LOG::open_index_file)

      1 - open the log-bin.index.
      2 - open the log-bin.~rec~.
      3 - for each file in log-bin.~rec~.
        3.1 Check if the file is in the log-bin.index and if so ignore it.
        3.2 Otherwise, delete it.

The third issue can be described as follows. 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, the routine was only
taking into account the dump threads and so if a slave was not connect the
file might be delete even though it was in use.

mysql-test/suite/binlog/r/binlog_index.result

+call mtr.add_suppression('Attempting backtrace');
+call mtr.add_suppression('MSYQL_BIN_LOG::purge_logs failed to process registered files that would be purged.');
+call mtr.add_suppression('MSYQL_BIN_LOG::open failed to sync the index file');
+call mtr.add_suppression('Turning logging off for the whole duration of the MySQL server process.');
+call mtr.add_suppression('MSYQL_BIN_LOG::purge_logs failed to clean registers before purging logs.');
 flush logs;
 flush logs;
 flush logs;
@@ -21,7 +26,6 @@ flush logs;
 *** must be a warning master-bin.000001 was not found ***
 Warnings:
 Warning	1612	Being purged log master-bin.000001 was not found
-Warning	1612	Being purged log master-bin.000001 was not found
 *** must show one record, of the active binlog, left in the index file after PURGE ***
 show binary logs;
 Log_name	File_size
@@ -37,4 +41,111 @@ 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;
+# crash_purge_before_update_index
+flush logs;
+SET SESSION debug="+d,crash_purge_before_update_index";
+purge binary logs TO 'master-bin.000002';
+ERROR HY000: Lost connection to MySQL server during query
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000001
+master-bin.000002
+master-bin.000003
+
+# crash_purge_non_critical_after_update_index
+flush logs;
+SET SESSION debug="+d,crash_purge_non_critical_after_update_index";
+purge binary logs TO 'master-bin.000004';
+ERROR HY000: Lost connection to MySQL server during query
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000004
+master-bin.000005
+
+# crash_purge_critical_after_update_index
+flush logs;
+SET SESSION debug="+d,crash_purge_critical_after_update_index";
+purge binary logs TO 'master-bin.000006';
+ERROR HY000: Lost connection to MySQL server during query
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000006
+master-bin.000007
+
+# crash_create_non_critical_before_update_index
+SET SESSION debug="+d,crash_create_non_critical_before_update_index";
+flush logs;
+ERROR HY000: Lost connection to MySQL server during query
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000006
+master-bin.000007
+master-bin.000008
+
+# crash_create_critical_before_update_index
+SET SESSION debug="+d,crash_create_critical_before_update_index";
+flush logs;
+ERROR HY000: Lost connection to MySQL server during query
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000006
+master-bin.000007
+master-bin.000008
+master-bin.000009
+
+# crash_create_after_update_index
+SET SESSION debug="+d,crash_create_after_update_index";
+flush logs;
+ERROR HY000: Lost connection to MySQL server during query
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000006
+master-bin.000007
+master-bin.000008
+master-bin.000009
+master-bin.000010
+master-bin.000011
+
+#
+# This should put the server in unsafe state and stop
+# accepting any command. If we inject a fault at this
+# point and continue the execution the server crashes.
+# Besides the flush command does not report an error.
+#
+# fault_injection_registering_index
+SET SESSION debug="+d,fault_injection_registering_index";
+flush logs;
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000006
+master-bin.000007
+master-bin.000008
+master-bin.000009
+master-bin.000010
+master-bin.000011
+master-bin.000012
+
+# fault_injection_updating_index
+SET SESSION debug="+d,fault_injection_updating_index";
+flush logs;
+SET @index=LOAD_FILE('MYSQLTEST_VARDIR/mysqld.1/data//master-bin.index');
+SELECT @index;
+@index
+master-bin.000006
+master-bin.000007
+master-bin.000008
+master-bin.000009
+master-bin.000010
+master-bin.000011
+master-bin.000012
+master-bin.000013
+
+SET SESSION debug="";
 End of tests

mysql-test/suite/binlog/t/binlog_index.test

@@ -3,6 +3,15 @@
 #
 source include/have_log_bin.inc;
 source include/not_embedded.inc;
+call mtr.add_suppression('Attempting backtrace');
+call mtr.add_suppression('MSYQL_BIN_LOG::purge_logs failed to process registered files that would be purged.');
+call mtr.add_suppression('MSYQL_BIN_LOG::open failed to sync the index file');
+call mtr.add_suppression('Turning logging off for the whole duration of the MySQL server process.');
+call mtr.add_suppression('MSYQL_BIN_LOG::purge_logs failed to clean registers before purging logs.');
+let $old=`select @@debug`;
+
+let $MYSQLD_DATADIR= `select @@datadir`;
+let $INDEX=$MYSQLD_DATADIR/master-bin.index;
 
 #
 # testing purge binary logs TO
@@ -13,7 +22,6 @@ flush logs;
 flush logs;
 
 source include/show_binary_logs.inc;
-let $MYSQLD_DATADIR= `select @@datadir`;
 remove_file $MYSQLD_DATADIR/master-bin.000001;
 
 # there must be a warning with file names
@@ -66,4 +74,159 @@ rmdir $MYSQLD_DATADIR/master-bin.000001;
 --disable_warnings
 reset master;
 --enable_warnings
+
+--echo # crash_purge_before_update_index
+flush logs;
+
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_purge_before_update_index";
+--error 2013
+purge binary logs TO 'master-bin.000002';
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+file_exists $MYSQLD_DATADIR/master-bin.000001;
+file_exists $MYSQLD_DATADIR/master-bin.000002;
+file_exists $MYSQLD_DATADIR/master-bin.000003;
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo # crash_purge_non_critical_after_update_index
+flush logs;
+
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_purge_non_critical_after_update_index";
+--error 2013
+purge binary logs TO 'master-bin.000004';
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000001;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000002;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000003;
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo # crash_purge_critical_after_update_index
+flush logs;
+
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_purge_critical_after_update_index";
+--error 2013
+purge binary logs TO 'master-bin.000006';
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000004;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000005;
+file_exists $MYSQLD_DATADIR/master-bin.000006;
+file_exists $MYSQLD_DATADIR/master-bin.000007;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000008;
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo # crash_create_non_critical_before_update_index
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_create_non_critical_before_update_index";
+--error 2013
+flush logs;
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+file_exists $MYSQLD_DATADIR/master-bin.000008;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000009;
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo # crash_create_critical_before_update_index
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_create_critical_before_update_index";
+--error 2013
+flush logs;
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+file_exists $MYSQLD_DATADIR/master-bin.000009;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000010;
+--error 1
+file_exists $MYSQLD_DATADIR/master-bin.000011;
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo # crash_create_after_update_index
+--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+SET SESSION debug="+d,crash_create_after_update_index";
+--error 2013
+flush logs;
+
+--enable_reconnect
+--source include/wait_until_connected_again.inc
+
+file_exists $MYSQLD_DATADIR/master-bin.000010;
+file_exists $MYSQLD_DATADIR/master-bin.000011;
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo #
+--echo # This should put the server in unsafe state and stop
+--echo # accepting any command. If we inject a fault at this
+--echo # point and continue the execution the server crashes.
+--echo # Besides the flush command does not report an error.
+--echo #
+
+--echo # fault_injection_registering_index
+SET SESSION debug="+d,fault_injection_registering_index";
+flush logs;
+--source include/restart_mysqld.inc
+
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+--echo # fault_injection_updating_index
+SET SESSION debug="+d,fault_injection_updating_index";
+flush logs;
+--source include/restart_mysqld.inc
+
+--chmod 0644 $INDEX
+-- replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
+-- eval SET @index=LOAD_FILE('$index')
+-- replace_regex /\.[\\\/]master/master/
+SELECT @index;
+
+eval SET SESSION debug="$old";
+
 --echo End of tests

sql/log.h

@@ -172,6 +172,10 @@ class MYSQL_LOG
             enum_log_type log_type,
             const char *new_name,
             enum cache_type io_cache_type_arg);
+  bool init_and_set_log_file_name(const char *log_name,
+                                  const char *new_name,
+                                  enum_log_type log_type_arg,
+                                  enum cache_type io_cache_type_arg);
   void init(enum_log_type log_type_arg,
             enum cache_type io_cache_type_arg);
   void close(uint exiting);
@@ -233,14 +237,15 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
   pthread_cond_t update_cond;
   ulonglong bytes_written;
   IO_CACHE index_file;
+  char index_file_name[FN_REFLEN];
   /*
-    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;
-  char index_file_name[FN_REFLEN];
+  IO_CACHE purge_index_file;
+  char purge_index_file_name[FN_REFLEN];
   /*
      The max size before rotation (usable only if log_type == LOG_BIN: binary
      logs and relay logs).
@@ -349,9 +354,10 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
             const char *new_name,
 	    enum cache_type io_cache_type_arg,
 	    bool no_auto_events_arg, ulong max_size,
-            bool null_created);
+            bool null_created,
+            bool need_mutex);
   bool open_index_file(const char *index_file_name_arg,
-                       const char *log_name);
+                       const char *log_name, bool need_mutex);
   /* Use this to start writing a new log file */
   void new_file();
 
@@ -384,6 +390,16 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
                  ulonglong *decrease_log_space);
   int purge_logs_before_date(time_t purge_time);
   int purge_first_log(Relay_log_info* rli, bool included);
+  int set_purge_index_file_name(const char *base_file_name);
+  int open_purge_index_file(bool destroy);
+  bool is_inited_purge_index_file();
+  int close_purge_index_file();
+  int clean_purge_index_file();
+  int sync_purge_index_file();
+  int register_purge_index_entry(const char* entry);
+  int register_create_index_entry(const char* entry);
+  int purge_index_entry(THD *thd, ulonglong *decrease_log_space,
+                        bool need_mutex);
   bool reset_logs(THD* thd);
   void close(uint exiting);
 

sql/mysqld.cc

@@ -3932,7 +3932,7 @@ a file name for --log-bin-index option", opt_binlog_index_name);
       my_free(opt_bin_logname, MYF(MY_ALLOW_ZERO_PTR));
       opt_bin_logname=my_strdup(buf, MYF(0));
     }
-    if (mysql_bin_log.open_index_file(opt_binlog_index_name, ln))
+    if (mysql_bin_log.open_index_file(opt_binlog_index_name, ln, TRUE))
     {
       unireg_abort(1);
     }
@@ -4096,7 +4096,7 @@ a file name for --log-bin-index option", opt_binlog_index_name);
   }
 
   if (opt_bin_log && mysql_bin_log.open(opt_bin_logname, LOG_BIN, 0,
-                                        WRITE_CACHE, 0, max_binlog_size, 0))
+                                        WRITE_CACHE, 0, max_binlog_size, 0, TRUE))
     unireg_abort(1);
 
 #ifdef HAVE_REPLICATION

sql/rpl_rli.cc

@@ -182,10 +182,10 @@ a file name for --relay-log-index option", opt_relaylog_index_name);
       note, that if open() fails, we'll still have index file open
       but a destructor will take care of that
     */
-    if (rli->relay_log.open_index_file(opt_relaylog_index_name, ln) ||
+    if (rli->relay_log.open_index_file(opt_relaylog_index_name, ln, TRUE) ||
         rli->relay_log.open(ln, LOG_BIN, 0, SEQ_READ_APPEND, 0,
                             (max_relay_log_size ? max_relay_log_size :
-                            max_binlog_size), 1))
+                            max_binlog_size), 1, TRUE))
     {
       pthread_mutex_unlock(&rli->data_lock);
       sql_print_error("Failed in open_log() called from init_relay_log_info()");