BUG#46166: MYSQL_BIN_LOG::new_file_impl is not propagating error

when generating new name.
      
If find_uniq_filename returns an error, then this error is not
being propagated upwards, and execution does not report error to
the user (although a entry in the error log is generated).
                  
Additionally, some more errors were ignored in new_file_impl:
- when writing the rotate event
- when reopening the index and binary log file
                  
This patch addresses this by propagating the error up in the
execution stack. Furthermore, when rotation of the binary log
fails, an incident event is written, because there may be a
chance that some changes for a given statement, were not properly
logged. For example, in SBR, LOAD DATA INFILE statement requires
more than one event to be logged, should rotation fail while
logging part of the LOAD DATA events, then the logged data would
become inconsistent with the data in the storage engine.

mysql-test/include/restart_mysqld.inc:
  Refactored restart_mysqld so that it is not hardcoded for
  mysqld.1, but rather for the current server.
mysql-test/suite/binlog/t/binlog_index.test:
  The error on open of index and binary log on new_file_impl 
  is now caught. Thence the user will get an error message. 
  We need to accomodate this change in the test case for the
  failing FLUSH LOGS.
mysql-test/suite/rpl/t/rpl_binlog_errors-master.opt:
  Sets max_binlog_size to 4096.
mysql-test/suite/rpl/t/rpl_binlog_errors.test:
  Added some test cases for asserting that the error is found 
  and reported.
sql/handler.cc:
  Catching error now returned by unlog (in ha_commit_trans) and 
  returning it.
sql/log.cc:
  Propagating errors from new_file_impl upwards. The errors that
  new_file_impl catches now are:
  - error on generate_new_name
  - error on writing the rotate event
  - error when opening the index or the binary log file.
sql/log.h:
  Changing declaration of:
  - rotate_and_purge
  - new_file
  - new_file_without_locking
  - new_file_impl
  - unlog
  They now return int instead of void.
sql/mysql_priv.h:
  Change signature of reload_acl_and_cache so that write_to_binlog
  is an int instead of bool.
sql/mysqld.cc:
  Redeclaring not_used var as int instead of bool.
sql/rpl_injector.cc:
  Changes to catch the return from rotate_and_purge.
sql/slave.cc:
  Changes to catch the return values for new_file and rotate_relay_log.
sql/slave.h:
  Changes to rotate_relay_log declaration (now returns int 
  instead of void).
sql/sql_load.cc:
  In SBR, some logging of LOAD DATA events goes through
  IO_CACHE_CALLBACK invocation at mf_iocache.c:_my_b_get. The
  IO_CACHE implementation is ignoring the return value for from
  these callbacks (pre_read and post_read), so we need to find out
  at the end of the execution if the error is set or not in THD.
sql/sql_parse.cc:
  Catching the rotate_relay_log and rotate_and_purge return values.
  Semantic change in reload_acl_and_cache so that we report errors
  in binlog interactions through the write_to_binlog output parameter.
  If there was any failure while rotating the binary log, we should
  then report the error to the client when handling SQLCOMM_FLUSH.
This commit is contained in:
Luis Soares 2010-11-30 23:32:51 +00:00
commit 647c619393
17 changed files with 958 additions and 73 deletions

View file

@ -1871,10 +1871,11 @@ static int find_uniq_filename(char *name)
*end='.';
length= (size_t) (end-start+1);
if (!(dir_info = my_dir(buff,MYF(MY_DONT_SORT))))
if ((DBUG_EVALUATE_IF("error_unique_log_filename", 1,
!(dir_info = my_dir(buff,MYF(MY_DONT_SORT))))))
{ // This shouldn't happen
strmov(end,".1"); // use name+1
DBUG_RETURN(0);
DBUG_RETURN(1);
}
file_info= dir_info->dir_entry;
for (i=dir_info->number_off_files ; i-- ; file_info++)
@ -1888,8 +1889,7 @@ static int find_uniq_filename(char *name)
my_dirend(dir_info);
*end++='.';
sprintf(end,"%06ld",max_found+1);
DBUG_RETURN(0);
DBUG_RETURN((sprintf(end,"%06ld",max_found+1) < 0));
}
@ -2101,6 +2101,8 @@ int MYSQL_LOG::generate_new_name(char *new_name, const char *log_name)
{
if (find_uniq_filename(new_name))
{
my_printf_error(ER_NO_UNIQUE_LOGFILE, ER(ER_NO_UNIQUE_LOGFILE),
MYF(ME_FATALERROR), log_name);
sql_print_error(ER(ER_NO_UNIQUE_LOGFILE), log_name);
return 1;
}
@ -3066,7 +3068,8 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd)
if (!thd->slave_thread)
need_start_event=1;
if (!open_index_file(index_file_name, 0, FALSE))
open(save_name, log_type, 0, io_cache_type, no_auto_events, max_size, 0, FALSE);
if ((error= open(save_name, log_type, 0, io_cache_type, no_auto_events, max_size, 0, FALSE)))
goto err;
my_free((uchar*) save_name, MYF(0));
err:
@ -3728,17 +3731,23 @@ bool MYSQL_BIN_LOG::is_active(const char *log_file_name_arg)
incapsulation 3) allows external access to the class without
a lock (which is not possible with private new_file_without_locking
method).
@retval
nonzero - error
*/
void MYSQL_BIN_LOG::new_file()
int MYSQL_BIN_LOG::new_file()
{
new_file_impl(1);
return new_file_impl(1);
}
void MYSQL_BIN_LOG::new_file_without_locking()
/*
@retval
nonzero - error
*/
int MYSQL_BIN_LOG::new_file_without_locking()
{
new_file_impl(0);
return new_file_impl(0);
}
@ -3747,19 +3756,23 @@ void MYSQL_BIN_LOG::new_file_without_locking()
@param need_lock Set to 1 if caller has not locked LOCK_log
@retval
nonzero - error
@note
The new file name is stored last in the index file
*/
void MYSQL_BIN_LOG::new_file_impl(bool need_lock)
int MYSQL_BIN_LOG::new_file_impl(bool need_lock)
{
char new_name[FN_REFLEN], *new_name_ptr, *old_name;
int error= 0, close_on_error= FALSE;
char new_name[FN_REFLEN], *new_name_ptr, *old_name, *file_to_open;
DBUG_ENTER("MYSQL_BIN_LOG::new_file_impl");
if (!is_open())
{
DBUG_PRINT("info",("log is closed"));
DBUG_VOID_RETURN;
DBUG_RETURN(error);
}
if (need_lock)
@ -3797,7 +3810,7 @@ void MYSQL_BIN_LOG::new_file_impl(bool need_lock)
We have to do this here and not in open as we want to store the
new file name in the current binary log file.
*/
if (generate_new_name(new_name, name))
if ((error= generate_new_name(new_name, name)))
goto end;
new_name_ptr=new_name;
@ -3811,7 +3824,13 @@ void MYSQL_BIN_LOG::new_file_impl(bool need_lock)
*/
Rotate_log_event r(new_name+dirname_length(new_name),
0, LOG_EVENT_OFFSET, is_relay_log ? Rotate_log_event::RELAY_LOG : 0);
r.write(&log_file);
if(DBUG_EVALUATE_IF("fault_injection_new_file_rotate_event", (error=close_on_error=TRUE), FALSE) ||
(error= r.write(&log_file)))
{
close_on_error= TRUE;
my_printf_error(ER_ERROR_ON_WRITE, ER(ER_CANT_OPEN_FILE), MYF(ME_FATALERROR), name, errno);
goto end;
}
bytes_written += r.data_written;
}
/*
@ -3839,17 +3858,56 @@ void MYSQL_BIN_LOG::new_file_impl(bool need_lock)
*/
/* reopen index binlog file, BUG#34582 */
if (!open_index_file(index_file_name, 0, FALSE))
open(old_name, log_type, new_name_ptr,
io_cache_type, no_auto_events, max_size, 1, FALSE);
file_to_open= index_file_name;
error= open_index_file(index_file_name, 0, FALSE);
if (!error)
{
/* reopen the binary log file. */
file_to_open= new_name_ptr;
error= open(old_name, log_type, new_name_ptr, io_cache_type,
no_auto_events, max_size, 1, FALSE);
}
/* handle reopening errors */
if (error)
{
my_printf_error(ER_CANT_OPEN_FILE, ER(ER_CANT_OPEN_FILE),
MYF(ME_FATALERROR), file_to_open, error);
close_on_error= TRUE;
}
my_free(old_name,MYF(0));
end:
if (error && close_on_error /* rotate or reopen failed */)
{
/*
Close whatever was left opened.
We are keeping the behavior as it exists today, ie,
we disable logging and move on (see: BUG#51014).
TODO: as part of WL#1790 consider other approaches:
- kill mysql (safety);
- try multiple locations for opening a log file;
- switch server to protected/readonly mode
- ...
*/
close(LOG_CLOSE_INDEX);
sql_print_error("Could not open %s for logging (error %d). "
"Turning logging off for the whole duration "
"of the MySQL server process. To turn it on "
"again: fix the cause, shutdown the MySQL "
"server and restart it.",
new_name_ptr, errno);
}
if (need_lock)
pthread_mutex_unlock(&LOCK_log);
pthread_mutex_unlock(&LOCK_index);
DBUG_VOID_RETURN;
DBUG_RETURN(error);
}
@ -3872,8 +3930,7 @@ bool MYSQL_BIN_LOG::append(Log_event* ev)
bytes_written+= ev->data_written;
DBUG_PRINT("info",("max_size: %lu",max_size));
if ((uint) my_b_append_tell(&log_file) > max_size)
new_file_without_locking();
error= new_file_without_locking();
err:
pthread_mutex_unlock(&LOCK_log);
signal_update(); // Safe as we don't call close
@ -3902,8 +3959,7 @@ bool MYSQL_BIN_LOG::appendv(const char* buf, uint len,...)
} while ((buf=va_arg(args,const char*)) && (len=va_arg(args,uint)));
DBUG_PRINT("info",("max_size: %lu",max_size));
if ((uint) my_b_append_tell(&log_file) > max_size)
new_file_without_locking();
error= new_file_without_locking();
err:
if (!error)
signal_update();
@ -4252,7 +4308,7 @@ MYSQL_BIN_LOG::flush_and_set_pending_rows_event(THD *thd,
if (!error)
{
signal_update();
rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
error= rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
}
}
@ -4448,7 +4504,9 @@ bool MYSQL_BIN_LOG::write(Log_event *event_info)
if (flush_and_sync())
goto err;
signal_update();
rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
if ((error= rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED)))
goto err;
}
error=0;
@ -4531,8 +4589,19 @@ bool general_log_write(THD *thd, enum enum_server_command command,
return FALSE;
}
void MYSQL_BIN_LOG::rotate_and_purge(uint flags)
/**
@note
If rotation fails, for instance the server was unable
to create a new log file, we still try to write an
incident event to the current log.
@retval
nonzero - error
*/
int MYSQL_BIN_LOG::rotate_and_purge(uint flags)
{
int error= 0;
DBUG_ENTER("MYSQL_BIN_LOG::rotate_and_purge");
#ifdef HAVE_REPLICATION
bool check_purge= false;
#endif
@ -4541,26 +4610,38 @@ void MYSQL_BIN_LOG::rotate_and_purge(uint flags)
if ((flags & RP_FORCE_ROTATE) ||
(my_b_tell(&log_file) >= (my_off_t) max_size))
{
new_file_without_locking();
if ((error= new_file_without_locking()))
/**
Be conservative... There are possible lost events (eg,
failing to log the Execute_load_query_log_event
on a LOAD DATA while using a non-transactional
table)!
We give it a shot and try to write an incident event anyway
to the current log.
*/
if (!write_incident(current_thd, FALSE))
flush_and_sync();
#ifdef HAVE_REPLICATION
check_purge= true;
#endif
}
if (!(flags & RP_LOCK_LOG_IS_ALREADY_LOCKED))
pthread_mutex_unlock(&LOCK_log);
#ifdef HAVE_REPLICATION
/*
NOTE: Run purge_logs wo/ holding LOCK_log
as it otherwise will deadlock in ndbcluster_binlog_index_purge_file
*/
if (check_purge && expire_logs_days)
if (!error && check_purge && expire_logs_days)
{
time_t purge_time= my_time(0) - expire_logs_days*24*60*60;
if (purge_time >= 0)
purge_logs_before_date(purge_time);
}
#endif
DBUG_RETURN(error);
}
uint MYSQL_BIN_LOG::next_file_id()
@ -4759,7 +4840,7 @@ bool MYSQL_BIN_LOG::write_incident(THD *thd, bool lock)
if (!error && !(error= flush_and_sync()))
{
signal_update();
rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
error= rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
}
pthread_mutex_unlock(&LOCK_log);
}
@ -4871,7 +4952,8 @@ bool MYSQL_BIN_LOG::write(THD *thd, IO_CACHE *cache, Log_event *commit_event,
pthread_mutex_unlock(&LOCK_prep_xids);
}
else
rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
if (rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED))
goto err;
}
VOID(pthread_mutex_unlock(&LOCK_log));
@ -5676,7 +5758,7 @@ int TC_LOG_MMAP::sync()
cookie points directly to the memory where xid was logged.
*/
void TC_LOG_MMAP::unlog(ulong cookie, my_xid xid)
int TC_LOG_MMAP::unlog(ulong cookie, my_xid xid)
{
PAGE *p=pages+(cookie/tc_log_page_size);
my_xid *x=(my_xid *)(data+cookie);
@ -5694,6 +5776,7 @@ void TC_LOG_MMAP::unlog(ulong cookie, my_xid xid)
if (p->waiters == 0) // the page is in pool and ready to rock
pthread_cond_signal(&COND_pool); // ping ... for overflow()
pthread_mutex_unlock(&p->lock);
return 0;
}
void TC_LOG_MMAP::close()
@ -5935,8 +6018,9 @@ int TC_LOG_BINLOG::log_xid(THD *thd, my_xid xid)
DBUG_RETURN(!binlog_end_trans(thd, trx_data, &xle, TRUE));
}
void TC_LOG_BINLOG::unlog(ulong cookie, my_xid xid)
int TC_LOG_BINLOG::unlog(ulong cookie, my_xid xid)
{
DBUG_ENTER("TC_LOG_BINLOG::unlog");
pthread_mutex_lock(&LOCK_prep_xids);
DBUG_ASSERT(prepared_xids > 0);
if (--prepared_xids == 0) {
@ -5944,7 +6028,7 @@ void TC_LOG_BINLOG::unlog(ulong cookie, my_xid xid)
pthread_cond_signal(&COND_prep_xids);
}
pthread_mutex_unlock(&LOCK_prep_xids);
rotate_and_purge(0); // as ::write() did not rotate
DBUG_RETURN(rotate_and_purge(0)); // as ::write() did not rotate
}
int TC_LOG_BINLOG::recover(IO_CACHE *log, Format_description_log_event *fdle)