#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]
