MDEV-13311 Presence of old logs in 10.2.7 will corrupt restored instance (change in behavior)

Mariabackup 10.2.7 would delete the redo log files after a successful
--prepare operation. If the user is manually copying the prepared files
instead of using the --copy-back option, it could happen that some old
redo log file would be preserved in the restored location. These old
redo log files could cause corruption of the restored data files when
the server is started up.

We prevent this scenario by creating a "poisoned" redo log file
ib_logfile0 at the end of the --prepare step. The poisoning consists
of simply truncating the file to an empty file. InnoDB will refuse
to start up on an empty redo log file.

copy_back(): Delete all redo log files in the target if the source
file ib_logfile0 is empty. (Previously we did this if the source
file is missing.)

SRV_OPERATION_RESTORE_EXPORT: A new variant of SRV_OPERATION_RESTORE
when the --export option is specified. In this mode, we will keep
deleting all redo log files, instead of truncating the first one.

delete_log_files(): Add a parameter for the first file to delete,
to be passed as 0 or 1.

innobase_start_or_create_for_mysql(): In mariabackup --prepare,
tolerate an empty ib_logfile0 file. Otherwise, require the first
redo log file to be longer than 4 blocks (2048 bytes). Unless
--export was specified, truncate the first log file at the
end of --prepare.

extra/mariabackup/backup_copy.cc

@@ -1707,7 +1707,8 @@ copy_back()
 	if it exists. */
 
 	ds_data = ds_create(dst_dir, DS_TYPE_LOCAL);
-	if (!file_exists("ib_logfile0")) {
+	MY_STAT stat_arg;
+	if (!my_stat("ib_logfile0", &stat_arg, MYF(0)) || !stat_arg.st_size) {
 		/* After completed --prepare, redo log files are redundant.
 		We must delete any redo logs at the destination, so that
 		the database will not jump to a different log sequence number

extra/mariabackup/xtrabackup.cc

@@ -4793,7 +4793,8 @@ xtrabackup_prepare_func(char** argv)
 		if (!ok) goto error_cleanup;
 	}
 
-	srv_operation = SRV_OPERATION_RESTORE;
+	srv_operation = xtrabackup_export
+		? SRV_OPERATION_RESTORE_EXPORT : SRV_OPERATION_RESTORE;
 
 	if (innodb_init_param()) {
 		goto error_cleanup;

mysql-test/suite/innodb/r/log_file_size.result

 CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
+SELECT * FROM INFORMATION_SCHEMA.ENGINES
+WHERE engine = 'innodb'
+AND support IN ('YES', 'DEFAULT', 'ENABLED');
+ENGINE	SUPPORT	COMMENT	TRANSACTIONS	XA	SAVEPOINTS
+FOUND 1 /InnoDB: Log file .*ib_logfile0 size 0 is too small/ in mysqld.1.err
+CHECK TABLE t1;
+Table	Op	Msg_type	Msg_text
+test.t1	check	status	OK
 BEGIN;
 INSERT INTO t1 VALUES (42);
 SELECT * FROM t1;

mysql-test/suite/innodb/t/log_file_size.test

@@ -23,14 +23,33 @@ call mtr.add_suppression("InnoDB: Log file .*ib_logfile[01].* size");
 call mtr.add_suppression("InnoDB: Unable to open .*ib_logfile0. to check native AIO read support");
 FLUSH TABLES;
 --enable_query_log
+let MYSQLD_DATADIR= `select @@datadir`;
+CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
+
+--source include/shutdown_mysqld.inc
+--move_file $MYSQLD_DATADIR/ib_logfile0 $MYSQLD_DATADIR/ib_logfile.old
+write_file $MYSQLD_DATADIR/ib_logfile0;
+EOF
+let $check_no_innodb=SELECT * FROM INFORMATION_SCHEMA.ENGINES
+WHERE engine = 'innodb'
+AND support IN ('YES', 'DEFAULT', 'ENABLED');
 
 --let $restart_parameters= --innodb-thread-concurrency=1 --innodb-log-file-size=1m --innodb-log-files-in-group=2
---source include/restart_mysqld.inc
+--source include/start_mysqld.inc
+
+eval $check_no_innodb;
+--remove_file $MYSQLD_DATADIR/ib_logfile0
+--move_file $MYSQLD_DATADIR/ib_logfile.old $MYSQLD_DATADIR/ib_logfile.0
+--source include/shutdown_mysqld.inc
+let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
+let SEARCH_PATTERN= InnoDB: Log file .*ib_logfile0 size 0 is too small;
+--source include/search_pattern_in_file.inc
+--source include/start_mysqld.inc
+CHECK TABLE t1;
 
 --let $restart_parameters= --innodb-thread-concurrency=100 --innodb-log-file-size=10M --innodb-log-files-in-group=2
 --source include/restart_mysqld.inc
 
-CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
 BEGIN;
 INSERT INTO t1 VALUES (42);
 
@@ -52,9 +71,7 @@ SELECT * FROM t1;
 
 INSERT INTO t1 VALUES (0),(123);
 
-let MYSQLD_DATADIR= `select @@datadir`;
 let SEARCH_ABORT = NOT FOUND;
-let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
 
 BEGIN;
 DELETE FROM t1 WHERE a>0;

mysql-test/suite/mariabackup/xb_file_key_management.result

@@ -9,6 +9,7 @@ INSERT INTO t VALUES('foobar2');
 # remove datadir
 # xtrabackup move back
 # restart server
+ib_logfile0
 SELECT * FROM t;
 c
 foobar1

mysql-test/suite/mariabackup/xb_file_key_management.test

@@ -24,6 +24,7 @@ exec $XTRABACKUP  --prepare --target-dir=$targetdir;
 --enable_result_log
 
 --list_files $targetdir ib_logfile*
+--cat_file $targetdir/ib_logfile0
 
 SELECT * FROM t;
 DROP TABLE t;

storage/innobase/include/srv0srv.h

@@ -508,10 +508,12 @@ enum srv_operation_mode {
 	SRV_OPERATION_NORMAL,
 	/** Mariabackup taking a backup */
 	SRV_OPERATION_BACKUP,
-	/** Mariabackup restoring a backup */
+	/** Mariabackup restoring a backup for subsequent --copy-back */
 	SRV_OPERATION_RESTORE,
 	/** Mariabackup restoring the incremental part of a backup */
-	SRV_OPERATION_RESTORE_DELTA
+	SRV_OPERATION_RESTORE_DELTA,
+	/** Mariabackup restoring a backup for subsequent --export */
+	SRV_OPERATION_RESTORE_EXPORT
 };
 
 /** Current mode of operation */

storage/innobase/log/log0recv.cc

@@ -1922,7 +1922,8 @@ void
 recv_apply_hashed_log_recs(bool last_batch)
 {
 	ut_ad(srv_operation == SRV_OPERATION_NORMAL
-	      || srv_operation == SRV_OPERATION_RESTORE);
+	      || srv_operation == SRV_OPERATION_RESTORE
+	      || srv_operation == SRV_OPERATION_RESTORE_EXPORT);
 
 	mutex_enter(&recv_sys->mutex);
 
@@ -1941,7 +1942,8 @@ recv_apply_hashed_log_recs(bool last_batch)
 	ut_ad(!last_batch == log_mutex_own());
 
 	recv_no_ibuf_operations = !last_batch
-		|| srv_operation == SRV_OPERATION_RESTORE;
+		|| srv_operation == SRV_OPERATION_RESTORE
+		|| srv_operation == SRV_OPERATION_RESTORE_EXPORT;
 
 	ut_d(recv_no_log_write = recv_no_ibuf_operations);
 
@@ -2960,7 +2962,8 @@ static
 dberr_t
 recv_init_missing_space(dberr_t err, const recv_spaces_t::const_iterator& i)
 {
-	if (srv_operation == SRV_OPERATION_RESTORE) {
+	if (srv_operation == SRV_OPERATION_RESTORE
+	    || srv_operation == SRV_OPERATION_RESTORE_EXPORT) {
 		ib::warn() << "Tablespace " << i->first << " was not"
 			" found at " << i->second.name << " when"
 			" restoring a (partial?) backup. All redo log"
@@ -3118,7 +3121,8 @@ recv_recovery_from_checkpoint_start(lsn_t flush_lsn)
 	dberr_t		err = DB_SUCCESS;
 
 	ut_ad(srv_operation == SRV_OPERATION_NORMAL
-	      || srv_operation == SRV_OPERATION_RESTORE);
+	      || srv_operation == SRV_OPERATION_RESTORE
+	      || srv_operation == SRV_OPERATION_RESTORE_EXPORT);
 
 	/* Initialize red-black tree for fast insertions into the
 	flush_list during recovery process. */

storage/innobase/srv/srv0start.cc

@@ -397,13 +397,14 @@ create_log_file(
 /** Delete all log files.
 @param[in,out]	logfilename	buffer for log file name
 @param[in]	dirnamelen	length of the directory path
-@param[in]	n_files		number of files to delete */
+@param[in]	n_files		number of files to delete
+@param[in]	i		first file to delete */
 static
 void
-delete_log_files(char* logfilename, size_t dirnamelen, unsigned n_files)
+delete_log_files(char* logfilename, size_t dirnamelen, uint n_files, uint i=0)
 {
 	/* Remove any old log files. */
-	for (unsigned i = 0; i < n_files; i++) {
+	for (; i < n_files; i++) {
 		sprintf(logfilename + dirnamelen, "ib_logfile%u", i);
 
 		/* Ignore errors about non-existent files or files
@@ -911,6 +912,7 @@ srv_undo_tablespaces_init(bool create_new_db)
 		}
 		/* fall through */
 	case SRV_OPERATION_RESTORE:
+	case SRV_OPERATION_RESTORE_EXPORT:
 		ut_ad(!create_new_db);
 
 		/* Check if any of the UNDO tablespace needs fix-up because
@@ -1321,6 +1323,7 @@ srv_shutdown_all_bg_threads()
 			break;
 		case SRV_OPERATION_NORMAL:
 		case SRV_OPERATION_RESTORE:
+		case SRV_OPERATION_RESTORE_EXPORT:
 			if (!buf_page_cleaner_is_active
 			    && os_aio_all_slots_free()) {
 				os_aio_wake_all_threads_at_shutdown();
@@ -1492,7 +1495,8 @@ innobase_start_or_create_for_mysql()
 	unsigned	i = 0;
 
 	ut_ad(srv_operation == SRV_OPERATION_NORMAL
-	      || srv_operation == SRV_OPERATION_RESTORE);
+	      || srv_operation == SRV_OPERATION_RESTORE
+	      || srv_operation == SRV_OPERATION_RESTORE_EXPORT);
 
 	if (srv_force_recovery == SRV_FORCE_NO_LOG_REDO) {
 		srv_read_only_mode = true;
@@ -1982,7 +1986,9 @@ innobase_start_or_create_for_mysql()
 			if (err == DB_NOT_FOUND) {
 				if (i == 0) {
 					if (srv_operation
-					    == SRV_OPERATION_RESTORE) {
+					    == SRV_OPERATION_RESTORE
+					    || srv_operation
+					    == SRV_OPERATION_RESTORE_EXPORT) {
 						return(DB_SUCCESS);
 					}
 					if (flushed_lsn
@@ -2046,6 +2052,26 @@ innobase_start_or_create_for_mysql()
 			}
 
 			if (i == 0) {
+				if (size == 0
+				    && (srv_operation
+					== SRV_OPERATION_RESTORE
+					|| srv_operation
+					== SRV_OPERATION_RESTORE_EXPORT)) {
+					/* Tolerate an empty ib_logfile0
+					from a previous run of
+					mariabackup --prepare. */
+					return(DB_SUCCESS);
+				}
+				/* The first log file must consist of
+				at least the following 512-byte pages:
+				header, checkpoint page 1, empty,
+				checkpoint page 2, redo log page(s) */
+				if (size <= OS_FILE_LOG_BLOCK_SIZE * 4) {
+					ib::error() << "Log file "
+						<< logfilename << " size "
+						<< size << " is too small";
+					return(srv_init_abort(DB_ERROR));
+				}
 				srv_log_file_size = size;
 			} else if (size != srv_log_file_size) {
 
@@ -2312,11 +2338,13 @@ innobase_start_or_create_for_mysql()
 
 		recv_recovery_from_checkpoint_finish();
 
-		if (srv_operation == SRV_OPERATION_RESTORE) {
+		if (srv_operation == SRV_OPERATION_RESTORE
+		    || srv_operation == SRV_OPERATION_RESTORE_EXPORT) {
 			/* After applying the redo log from
 			SRV_OPERATION_BACKUP, flush the changes
-			to the data files and delete the log file.
-			No further change to InnoDB files is needed. */
+			to the data files and truncate or delete the log.
+			Unless --export is specified, no further change to
+			InnoDB files is needed. */
 			ut_ad(!srv_force_recovery);
 			ut_ad(srv_n_log_files_found <= 1);
 			ut_ad(recv_no_log_write);
@@ -2326,8 +2354,18 @@ innobase_start_or_create_for_mysql()
 			fil_close_log_files(true);
 			log_group_close_all();
 			if (err == DB_SUCCESS) {
+				bool trunc = srv_operation
+					== SRV_OPERATION_RESTORE;
+				/* Delete subsequent log files. */
 				delete_log_files(logfilename, dirnamelen,
-						 srv_n_log_files_found);
+						 srv_n_log_files_found, trunc);
+				if (trunc) {
+					/* Truncate the first log file. */
+					strcpy(logfilename + dirnamelen,
+					       "ib_logfile0");
+					FILE* f = fopen(logfilename, "w");
+					fclose(f);
+				}
 			}
 			return(err);
 		}
@@ -2792,6 +2830,7 @@ innodb_shutdown()
 	case SRV_OPERATION_BACKUP:
 	case SRV_OPERATION_RESTORE:
 	case SRV_OPERATION_RESTORE_DELTA:
+	case SRV_OPERATION_RESTORE_EXPORT:
 		fil_close_all_files();
 		break;
 	case SRV_OPERATION_NORMAL:

storage/innobase/trx/trx0trx.cc

@@ -620,6 +620,7 @@ trx_free_prepared(
 		 && trx->is_recovered
 		 && (!srv_was_started
 		     || srv_operation == SRV_OPERATION_RESTORE
+		     || srv_operation == SRV_OPERATION_RESTORE_EXPORT
 		     || srv_read_only_mode
 		     || srv_force_recovery >= SRV_FORCE_NO_TRX_UNDO)));
 	ut_a(trx->magic_n == TRX_MAGIC_N);