#At file:///ext/mysql/bzr/backup/bug40305/
2734 Rafal Somla 2008-12-09
Bug #40305 - Backup: Bad feedback when BACKUP/RESTORE operation aborted.
This patch refactors the code reporting termination of BACKUP/RESTORE statement.
After the changes "Backup/Restore completed" is shown only if operation has been
completed. In case of abnormal termination (error, interruption) a warning
"Operation aborted" or "Operation aborted - data might be corrupted" is logged.
The latter is in the case of RESTORE operation which has modified some data in
the server.
The main changes are:
- Adding new methods to backup::Logger for reporting successful completion of an
operation and the fact that data has been modified.
- Slightly change semantics of report_stop() which now does not report state
changes - it is done in appropriate report_completed() or report_error().
- Make sure that report_stop() is always called - now it is done in
Backup_restore_ctx::close() which is called from the destructor.
- Change the logic for removing backup file (in case BACKUP operation is not
completed). Before this was guarded by explicit m_remove_loc flag. Now we can
directly check if BACKUP operation has been completed successfully (i.e.
report_completed() was called) or not.
Note: the new functionality is covered by existing test cases.
modified:
mysql-test/suite/backup/r/backup_errors.result
mysql-test/suite/backup/r/backup_logs_purge.result
mysql-test/suite/backup/t/backup_logs_purge.test
sql/backup/backup_kernel.h
sql/backup/data_backup.cc
sql/backup/kernel.cc
sql/backup/logger.h
sql/share/errmsg.txt
per-file messages:
mysql-test/suite/backup/r/backup_errors.result
Result change - now additional warning about statement interruption is pushed on
the error stack.
mysql-test/suite/backup/t/backup_logs_purge.test
Update debug synchronization points - BACKUP/RESTORE must be stopped before
state change to "Completed" is reported in backup progress log. This state
change is reported by report_completed().
sql/backup/backup_kernel.h
- Document the states of Backup_restore_ctx class.
- Remove m_remove_loc member which is no longer used.
- Add m_stop_time member for reporting stop time.
sql/backup/data_backup.cc
Report changes of data when restoring table data.
sql/backup/kernel.cc
- Make sure that report_stop() is always called - now it is done in
Backup_restore_ctx::close() which is called from the destructor.
- Change the logic for removing backup file: instead of using explicit
m_remove_loc flag, decide based on whether BACKUP operation has completed
successfully or not (as now this information is available).
- Call Backup_restore_ctx::close() in do_backup() and do_restore(), when
operation is completed - no need to wait any longer.
- Report data changes when objects are created in bcat_create_item() and
restore_triggers_and_events().
sql/backup/logger.h
- Add new backup::Logger() methods: report_completed() and
report_data_changed().
- Slightly change semantics of report_stop() which now does not report state
changes - it is done in appropriate report_completed() or report_error().
sql/share/errmsg.txt
Add messages for reporting early termination of a statement.
=== modified file 'mysql-test/suite/backup/r/backup_errors.result'
--- a/mysql-test/suite/backup/r/backup_errors.result 2008-12-08 11:24:51 +0000
+++ b/mysql-test/suite/backup/r/backup_errors.result 2008-12-09 11:23:37 +0000
@@ -10,12 +10,14 @@ ERROR HY000: Malformed file path ''
SHOW WARNINGS;
Level Code Message
Error # Malformed file path ''
+Warning # Operation aborted
BACKUP DATABASE adb TO "bdb/t1.frm";
ERROR HY000: Can't create/write to file 'MYSQLTEST_VARDIR/master-data/bdb/t1.frm'
(Errcode: #)
SHOW WARNINGS;
Level Code Message
Error # Can't create/write to file 'MYSQLTEST_VARDIR/master-data/bdb/t1.frm' (Errcode: #)
Error # Can't write to backup location 'bdb/t1.frm'
+Warning # Operation aborted
BACKUP DATABASE adb TO "test.bak";
backup_id
#
@@ -27,6 +29,7 @@ SHOW WARNINGS;
Level Code Message
Error # Can't create/write to file 'MYSQLTEST_VARDIR/master-data/test.bak' (Errcode: #)
Error # Can't write to backup location 'test.bak'
+Warning # Operation aborted
DROP DATABASE IF EXISTS foo;
DROP DATABASE IF EXISTS bar;
BACKUP DATABASE foo TO 'test.bak';
@@ -34,11 +37,13 @@ ERROR 42000: Unknown database 'foo'
SHOW WARNINGS;
Level Code Message
Error 1049 Unknown database 'foo'
+Warning 1757 Operation aborted
BACKUP DATABASE test,foo,bdb,bar TO 'test.bak';
ERROR 42000: Unknown database 'foo,bar'
SHOW WARNINGS;
Level Code Message
Error # Unknown database 'foo,bar'
+Warning # Operation aborted
BACKUP DATABASE foo,test,bar,foo TO 'test.bak';
ERROR 42000: Not unique database: 'foo'
use adb;
@@ -71,36 +76,42 @@ ERROR HY000: Database 'mysql' cannot be
SHOW WARNINGS;
Level Code Message
Error # Database 'mysql' cannot be included in a backup
+Warning # Operation aborted
Backup of mysql, information_schema scenario 2
BACKUP DATABASE information_schema TO 't.bak';
ERROR HY000: Database 'information_schema' cannot be included in a backup
SHOW WARNINGS;
Level Code Message
Error # Database 'information_schema' cannot be included in a backup
+Warning # Operation aborted
Backup of mysql, information_schema scenario 3
BACKUP DATABASE mysql, information_schema TO 't.bak';
ERROR HY000: Database 'mysql' cannot be included in a backup
SHOW WARNINGS;
Level Code Message
Error # Database 'mysql' cannot be included in a backup
+Warning # Operation aborted
Backup of mysql, information_schema scenario 4
BACKUP DATABASE mysql, test TO 't.bak';
ERROR HY000: Database 'mysql' cannot be included in a backup
SHOW WARNINGS;
Level Code Message
Error # Database 'mysql' cannot be included in a backup
+Warning # Operation aborted
Backup of mysql, information_schema scenario 5
BACKUP DATABASE information_schema, test TO 't.bak';
ERROR HY000: Database 'information_schema' cannot be included in a backup
SHOW WARNINGS;
Level Code Message
Error # Database 'information_schema' cannot be included in a backup
+Warning # Operation aborted
Backup of mysql, information_schema scenario 6
BACKUP DATABASE mysql, information_schema, test TO 't.bak';
ERROR HY000: Database 'mysql' cannot be included in a backup
SHOW WARNINGS;
Level Code Message
Error # Database 'mysql' cannot be included in a backup
+Warning # Operation aborted
Making copies of progress tables.
CREATE TABLE IF NOT EXISTS test.ob_copy LIKE mysql.backup_history;
CREATE TABLE IF NOT EXISTS test.obp_copy LIKE mysql.backup_progress;
=== modified file 'mysql-test/suite/backup/r/backup_logs_purge.result'
--- a/mysql-test/suite/backup/r/backup_logs_purge.result 2008-11-17 09:57:51 +0000
+++ b/mysql-test/suite/backup/r/backup_logs_purge.result 2008-12-09 11:23:37 +0000
@@ -252,7 +252,7 @@ count(*)
24
SET SESSION debug="+d,set_backup_id";
con2: Activate sync points for the backup statement.
-SET DEBUG_SYNC= 'before_backup_done SIGNAL ready WAIT_FOR proceed';
+SET DEBUG_SYNC= 'before_backup_completed SIGNAL ready WAIT_FOR proceed';
BACKUP DATABASE backup_logs to 'backup5.bak';
con1: Wait for the backup to be ready.
SET DEBUG_SYNC= 'now WAIT_FOR ready';
@@ -305,7 +305,7 @@ SELECT count(*) FROM mysql.backup_progre
count(*)
13
con2: Activate sync points for the backup statement.
-SET DEBUG_SYNC= 'before_restore_done SIGNAL ready WAIT_FOR proceed';
+SET DEBUG_SYNC= 'before_restore_completed SIGNAL ready WAIT_FOR proceed';
RESTORE FROM 'backup5.bak' OVERWRITE;
con1: Wait for the backup to be ready.
SET DEBUG_SYNC= 'now WAIT_FOR ready';
=== modified file 'mysql-test/suite/backup/t/backup_logs_purge.test'
--- a/mysql-test/suite/backup/t/backup_logs_purge.test 2008-11-17 09:57:51 +0000
+++ b/mysql-test/suite/backup/t/backup_logs_purge.test 2008-12-09 11:23:37 +0000
@@ -274,7 +274,7 @@ SET SESSION debug="+d,set_backup_id";
# it writes the history log and last complete log entry.
#
--echo con2: Activate sync points for the backup statement.
-SET DEBUG_SYNC= 'before_backup_done SIGNAL ready WAIT_FOR proceed';
+SET DEBUG_SYNC= 'before_backup_completed SIGNAL ready WAIT_FOR proceed';
SEND BACKUP DATABASE backup_logs to 'backup5.bak';
connection con1;
@@ -328,7 +328,7 @@ connection con2;
# it writes the history log and last complete log entry.
#
--echo con2: Activate sync points for the backup statement.
-SET DEBUG_SYNC= 'before_restore_done SIGNAL ready WAIT_FOR proceed';
+SET DEBUG_SYNC= 'before_restore_completed SIGNAL ready WAIT_FOR proceed';
SEND RESTORE FROM 'backup5.bak' OVERWRITE;
connection con1;
=== modified file 'sql/backup/backup_kernel.h'
--- a/sql/backup/backup_kernel.h 2008-11-25 17:44:19 +0000
+++ b/sql/backup/backup_kernel.h 2008-12-09 11:23:37 +0000
@@ -99,9 +99,27 @@ class Backup_restore_ctx: public backup:
/**
@brief State of a context object.
-
- Backup/restore can be performed only if object is prepared for that
- operation.
+
+ The following diagram illustrates the states in which a context object
+ can be and how the state changes as a result of calling public methods.
+ Methods which are not listed are forbidden in a given state.
+ @verbatim
+ CREATED prepare_for_backup() -> PREPARED_FOR_BACKUP
+ prepare_for_restore() -> PREPARED_FOR_RESTORE
+ close() -> CLOSED
+
+ PREPARED_FOR_BACKUP do_backup() -> CLOSED
+ close() -> CLOSED
+
+ PREPARED_FOR_RESTORE do_restore() -> CLOSED
+ close() -> CLOSED
+
+ CLOSED close() -> CLOSED
+ @endverbatim
+
+ @note An instance of the context class can be used only once -- when it
+ moves to CLOSED state no methods can be called except for close() which does
+ nothing in that case.
*/
enum { CREATED,
PREPARED_FOR_BACKUP,
@@ -129,9 +147,6 @@ class Backup_restore_ctx: public backup:
::String m_path; ///< Path to where the backup image file is located.
- /** If true, the backup image file is deleted at clean-up time. */
- bool m_remove_loc;
-
backup::Stream *m_stream; ///< Pointer to the backup stream object, if opened.
backup::Image_info *m_catalog; ///< Pointer to the image catalogue object.
@@ -160,6 +175,12 @@ class Backup_restore_ctx: public backup:
int report_stream_open_failure(int open_error, const LEX_STRING *location);
+ /**
+ For saving timestamp of the moment when the operation has been ended, so
+ that it can be correctly reported.
+ */
+ time_t m_stop_time;
+
friend int backup_init();
friend void backup_shutdown();
friend bstream_byte* bstream_alloc(unsigned long int);
@@ -207,8 +228,6 @@ void Backup_restore_ctx::disable_fkey_co
inline
int Backup_restore_ctx::fatal_error(int error_code)
{
- m_remove_loc= TRUE;
-
if (m_error)
return m_error;
=== modified file 'sql/backup/data_backup.cc'
--- a/sql/backup/data_backup.cc 2008-11-26 10:05:19 +0000
+++ b/sql/backup/data_backup.cc 2008-12-09 11:23:37 +0000
@@ -1445,6 +1445,12 @@ int restore_table_data(THD *thd, Restore
// Create restore drivers
result_t res;
+ /**
+ Report that data is being modyfied here because we don't know when a restore
+ driver starts doing it, after it has been created.
+ */
+ log.report_data_changed();
+
for (uint n=0; n < info.snap_count(); ++n)
{
active[n]= drv[n]= NULL;
=== modified file 'sql/backup/kernel.cc'
--- a/sql/backup/kernel.cc 2008-11-28 10:10:39 +0000
+++ b/sql/backup/kernel.cc 2008-12-09 11:23:37 +0000
@@ -273,8 +273,6 @@ int send_error(Backup_restore_ctx &conte
va_end(args);
}
- if (context.backup::Logger::m_state == backup::Logger::RUNNING)
- context.report_stop(my_time(0), FALSE); // FASLE = no success
return error_code;
}
@@ -379,9 +377,9 @@ pthread_mutex_t Backup_restore_ctx::run_
Backup_restore_ctx::Backup_restore_ctx(THD *thd)
:Logger(thd), m_state(CREATED), m_thd_options(thd->options),
- m_error(0), m_remove_loc(FALSE), m_stream(NULL),
+ m_error(0), m_stream(NULL),
m_catalog(NULL), mem_alloc(NULL), m_tables_locked(FALSE),
- m_engage_binlog(FALSE)
+ m_engage_binlog(FALSE), m_stop_time(0)
{
/*
Check for progress tables.
@@ -628,9 +626,6 @@ Backup_restore_ctx::prepare_for_backup(S
return NULL;
}
- // Mark that the file should be removed unless operation completes successfuly
- m_remove_loc= TRUE;
-
int my_open_status= s->open();
if (my_open_status != 0)
{
@@ -926,6 +921,23 @@ int Backup_restore_ctx::close()
using namespace backup;
/*
+ Report end of the operation which has started if it has not been done
+ before (Logger is in RUNNIG state).
+ */
+ if (Logger::m_state == RUNNING)
+ {
+ // If m_stop_time has not been recorded so far, do it now.
+ if (!m_stop_time)
+ {
+ m_stop_time= my_time(0);
+ if (m_catalog)
+ m_catalog->save_end_time(m_stop_time);
+ }
+
+ report_stop(m_stop_time);
+ }
+
+ /*
Allow slaves connect after restore is complete.
*/
obs::disable_slave_connections(FALSE);
@@ -936,8 +948,6 @@ int Backup_restore_ctx::close()
if (m_engage_binlog)
obs::engage_binlog(TRUE);
- time_t when= my_time(0);
-
// unlock tables if they are still locked
unlock_tables(); // Never errors
@@ -948,7 +958,7 @@ int Backup_restore_ctx::close()
m_thd->options= m_thd_options;
- // close stream
+ // close stream if not closed already (in which case m_steam is NULL)
if (m_stream && !m_stream->close())
{
@@ -956,16 +966,13 @@ int Backup_restore_ctx::close()
fatal_error(report_error(ER_BACKUP_CLOSE));
}
- if (m_catalog)
- m_catalog->save_end_time(when); // Note: no errors.
-
/*
- Remove the location, if asked for.
+ Remove the location if it is BACKUP operation and it has not completed
+ sucessfully.
- Important: This is done only for backup operation - RESTORE should never
- remove the specified backup image!
+ Important: RESTORE should never remove the specified backup image!
*/
- if (m_remove_loc && m_state == PREPARED_FOR_BACKUP)
+ if (m_state == PREPARED_FOR_BACKUP && !m_completed)
{
int ret= my_delete(m_path.c_ptr(), MYF(0));
@@ -973,17 +980,8 @@ int Backup_restore_ctx::close()
Ignore ENOENT error since it is ok if the file doesn't exist.
*/
if (ret && my_errno != ENOENT)
- fatal_error(report_error(ER_CANT_DELETE_FILE, m_path.c_ptr(), my_errno));
- }
-
- /* We report completion of the operation only if no errors were detected,
- and logger has been initialized.
- */
- if (!m_error)
- {
- if (backup::Logger::m_state == backup::Logger::RUNNING)
{
- report_stop(when, TRUE);
+ fatal_error(report_error(ER_CANT_DELETE_FILE, m_path.c_ptr(), my_errno));
}
}
@@ -1056,23 +1054,23 @@ int Backup_restore_ctx::do_backup()
if (ret)
DBUG_RETURN(fatal_error(ret));
+ m_stop_time= my_time(0);
+ info.save_end_time(m_stop_time);
+
DBUG_PRINT("backup",("Writing summary"));
ret= write_summary(info, s);
if (ret)
DBUG_RETURN(fatal_error(report_error(ER_BACKUP_WRITE_SUMMARY)));
- /*
- Now backup image has been written. Set m_remove_loc to FALSE, so that the
- backup file is not removed in Backup_restore_ctx::close().
- */
- m_remove_loc= FALSE;
+ DEBUG_SYNC(m_thd, "before_backup_completed");
+ report_completed(); // Never errors
report_stats_post(info); // Never errors
DBUG_PRINT("backup",("Backup done."));
DEBUG_SYNC(m_thd, "before_backup_done");
- DBUG_RETURN(0);
+ DBUG_RETURN(close());
}
/**
@@ -1128,6 +1126,8 @@ int Backup_restore_ctx::restore_triggers
case BSTREAM_IT_TRIGGER:
DBUG_ASSERT(obj->m_obj_ptr);
+ // Report that we are modyfinig data.
+ log.report_data_changed();
if (obj->m_obj_ptr->execute(m_thd))
{
delete it;
@@ -1152,11 +1152,15 @@ int Backup_restore_ctx::restore_triggers
Image_info::Obj *ev;
while ((ev= it++))
+ {
+ // Report that we are modyfinig data.
+ log.report_data_changed();
if (ev->m_obj_ptr->execute(m_thd))
{
int ret= report_error(ER_BACKUP_CANT_RESTORE_EVENT,ev->describe(buf));
DBUG_RETURN(fatal_error(ret));
};
+ }
DBUG_RETURN(0);
}
@@ -1274,6 +1278,11 @@ int Backup_restore_ctx::do_restore(bool
DBUG_PRINT("restore",("Done."));
+ DEBUG_SYNC(m_thd, "before_restore_completed");
+ m_stop_time= my_time(0);
+ info.save_end_time(m_stop_time);
+ report_completed(); // Never errors
+
err= read_summary(info, s);
if (err)
DBUG_RETURN(fatal_error(report_error(ER_BACKUP_READ_SUMMARY)));
@@ -1291,7 +1300,7 @@ int Backup_restore_ctx::do_restore(bool
DEBUG_SYNC(m_thd, "before_restore_done");
- DBUG_RETURN(0);
+ DBUG_RETURN(close());
}
/**
@@ -2015,6 +2024,9 @@ int bcat_create_item(st_bstream_image_he
}
}
+ // Report that we are modyfinig data.
+ log.report_data_changed();
+
if (sobj->execute(thd))
{
log.report_error(create_err, desc);
=== modified file 'sql/backup/logger.h'
--- a/sql/backup/logger.h 2008-11-25 17:44:19 +0000
+++ b/sql/backup/logger.h 2008-12-09 11:23:37 +0000
@@ -54,7 +54,7 @@ class Logger
int log_error(int error_code, ...);
void report_start(time_t);
- void report_stop(time_t, bool);
+ void report_stop(time_t);
void report_state(enum_backup_state);
void report_vp_time(time_t, bool);
void report_binlog_pos(const st_bstream_binlog_pos&);
@@ -63,6 +63,9 @@ class Logger
void report_backup_file(char * path);
void report_stats_pre(const Image_info&);
void report_stats_post(const Image_info&);
+ void report_data_changed();
+ void report_completed();
+
ulonglong get_op_id() const
{
DBUG_ASSERT(backup_log);
@@ -76,6 +79,8 @@ class Logger
/// Thread in which this logger is used.
THD *m_thd;
+ bool m_completed; ///< Has @c report_completed() been called?
+ bool m_data_changed; ///< Has @c report_data_changed() been called?
int v_report_error(log_level::value, int, va_list);
int v_write_message(log_level::value, int, const char*, va_list);
@@ -95,8 +100,9 @@ class Logger
inline
Logger::Logger(THD *thd)
- :m_type(BACKUP), m_state(CREATED), m_thd(thd), m_push_errors(TRUE),
- m_error_reported(FALSE), backup_log(0)
+ :m_type(BACKUP), m_state(CREATED), m_thd(thd),
+ m_completed(FALSE), m_data_changed(FALSE),
+ m_push_errors(TRUE), m_error_reported(FALSE), backup_log(0)
{}
inline
@@ -187,13 +193,62 @@ void Logger::report_start(time_t when)
backup_log->state(BUP_RUNNING);
}
+/**
+ Report that the operation has completed successfully.
+
+ @note This method can be called only after @c report_start().
+*/
+inline
+void Logger::report_completed()
+{
+ DBUG_ASSERT(m_state == RUNNING);
+ if (m_completed)
+ return;
+
+ report_error(log_level::INFO, m_type == BACKUP ? ER_BACKUP_BACKUP_DONE
+ : ER_BACKUP_RESTORE_DONE);
+ report_state(BUP_COMPLETE);
+ m_completed= TRUE;
+}
+
+/**
+ Report that destructive data changes have been made.
+
+ @note This method can be called only in RUNNING stae.
+*/
+inline
+void Logger::report_data_changed()
+{
+ DBUG_ASSERT(m_state == RUNNING);
+ m_data_changed= TRUE;
+}
+
/**
Report end of the operation.
+
+ @param[in] when time when the operation has ended.
+
+ This method should be called to report the fact that backup/restore operation
+ has ended. This might be normal termination after completing the operation
+ (report_completed() has been called before), or an early termination due to
+ detected error or user interruption.
+
+ The method will log the stop time. If this is abnormal termination, a warning
+ will be logged. Normally it is ER_OPERATION_ABORTED warning but if a restore
+ operation has been interrupted and report_changed_data() has been called
+ before, ER_OPERATION_ABORTED_CORRUPTED warning will be logged, to warn the
+ user about the possibility of data corruption.
- @param[in] success indicates if the operation ended successfuly
+ @note It is safe to call this method several times. Only the first call is
+ meaningful.
+
+ @note This method must be called to write the backup history log entry for
+ the operation.
+
+ @note This method must be called after @c report_start().
*/
inline
-void Logger::report_stop(time_t when, bool success)
+void Logger::report_stop(time_t when)
{
if (m_state == DONE)
return;
@@ -201,12 +256,25 @@ void Logger::report_stop(time_t when, bo
DBUG_ASSERT(m_state == RUNNING);
DBUG_ASSERT(backup_log);
- report_error(log_level::INFO, m_type == BACKUP ? ER_BACKUP_BACKUP_DONE
- : ER_BACKUP_RESTORE_DONE);
+ if (!m_completed)
+ {
+ // This is abnormal termination - issue correct warning
+ if (m_type == RESTORE && m_data_changed)
+ report_error(log_level::WARNING, ER_OPERATION_ABORTED_CORRUPTED);
+ else
+ report_error(log_level::WARNING, ER_OPERATION_ABORTED);
+ }
+
+ // Report stop time to backup logs.
backup_log->stop(when);
- backup_log->state(success ? BUP_COMPLETE : BUP_ERRORS);
+
+ /*
+ Since the operation has completed, we can now write the backup history log
+ entry describing it.
+ */
backup_log->write_history();
+
m_state= DONE;
}
=== modified file 'sql/share/errmsg.txt'
--- a/sql/share/errmsg.txt 2008-12-08 11:24:51 +0000
+++ b/sql/share/errmsg.txt 2008-12-09 11:23:37 +0000
@@ -6442,3 +6442,7 @@ ER_BACKUP_BACKUP_DBS
eng "Backing up %u database(s) %.220s"
ER_BACKUP_RESTORE_DBS
eng "Restoring %u database(s) %.220s"
+ER_OPERATION_ABORTED
+ eng "Operation aborted"
+ER_OPERATION_ABORTED_CORRUPTED
+ eng "Operation aborted - data might be corrupted"