Adding more logging for xtrabackup.xb_with_logs and changing log oupu…

…t location

Summary:
xtrabackup.xb_with_logs occasionally failed with data corruption
detected during copy phase. The failure happened only on 32K page size,
and often on the first page of a new chunk (we saw it happens at page
256, 257, 384, 448, and 512).

I add some extra logging only for XtraBackup so we can have more
insights on the cause of page corruption.

I also change the log output directory to MYSQLTEST_VARDIR/log. There
are four log files: xtrabackup_copy_log, xtrabackup_restore_log,
xtrabackup_moveback_log, gtid_stmt,  which should really go into the log
directory instead of tmp directory. This also let Jenkins to save those
log files in test failures.

Test Plan: Sanity tests on xtrabackup suite

Reviewers: santoshb, jtolmer

Reviewed By: jtolmer

Subscribers: webscalesql-eng

Differential Revision: https://reviews.facebook.net/D53559

mysql-test/suite/xtrabackup/include/xb_run.sh

@@ -6,6 +6,7 @@ ibbackup_opt="--ibbackup=${MYSQL_XTRABACKUP}"
 defaults_file_opt="--defaults-file=${MYSQLTEST_VARDIR}/my.cnf"
 backup_dir="${MYSQLTEST_VARDIR}/backup"
 dest_data_dir="${MYSQLTEST_VARDIR}/mysqld.2/data/"
+log_dir="${MYSQLTEST_VARDIR}/log"
 
 mkdir -p $backup_dir
 rm -rf $backup_dir/*
@@ -17,24 +18,24 @@ mysql_dir=$(echo $MYSQL | awk '{print $1}' | xargs dirname)
 PATH=$mysql_dir:$PATH
 
 echo "innobackupex copy phase"
-if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.1 $ibbackup_opt $backup_dir > ${MYSQL_TMP_DIR}/xtrabackup_copy_log 2>&1
+if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.1 $ibbackup_opt $backup_dir > $log_dir/xtrabackup_copy_log 2>&1
 then
-  tail ${MYSQL_TMP_DIR}/xtrabackup_copy_log
+  tail $log_dir/xtrabackup_copy_log
   exit 1
 fi
-backup_dir=($(grep "innobackupex: Backup created in directory" ${MYSQL_TMP_DIR}/xtrabackup_copy_log | awk -F\' '{ print $2}'))
+backup_dir=($(grep "innobackupex: Backup created in directory" $log_dir/xtrabackup_copy_log | awk -F\' '{ print $2}'))
 
 echo "innobackupex apply-log phase"
-if ! $MYSQL_INNOBACKUPEX $ibbackup_opt $backup_dir --apply-log > ${MYSQL_TMP_DIR}/xtrabackup_restore_log 2>&1
+if ! $MYSQL_INNOBACKUPEX $ibbackup_opt $backup_dir --apply-log > $log_dir/xtrabackup_restore_log 2>&1
 then
-  tail ${MYSQL_TMP_DIR}/xtrabackup_restore_log
+  tail $log_dir/xtrabackup_restore_log
   exit 1
 fi
 
 echo "innobackupex move-back phase"
-if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.2 $ibbackup_opt $backup_dir --move-back > ${MYSQL_TMP_DIR}/xtrabackup_moveback_log 2>&1
+if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.2 $ibbackup_opt $backup_dir --move-back > $log_dir/xtrabackup_moveback_log 2>&1
 then
-  tail ${MYSQL_TMP_DIR}/xtrabackup_moveback_log
+  tail $log_dir/xtrabackup_moveback_log
   exit 1
 fi
 cp $backup_dir/ib_logfile* $dest_data_dir

mysql-test/suite/xtrabackup/include/xb_setup_replication.sh

@@ -1,6 +1,6 @@
 set -e
 
-binlog_line=($(grep -m 1 -o "Last MySQL binlog file position 0 [0-9]*, file name .*\.[0-9]*" ${MYSQL_TMP_DIR}/xtrabackup_restore_log))
+binlog_line=($(grep -m 1 -o "Last MySQL binlog file position 0 [0-9]*, file name .*\.[0-9]*" ${MYSQLTEST_VARDIR}/log/xtrabackup_restore_log))
 binlog_pos=${binlog_line[6]%?}
 binlog_file=${binlog_line[9]}
 sql="change master to master_host='127.0.0.1', master_port=${MASTER_MYPORT}, master_user='root', master_log_file='$binlog_file', master_log_pos=$binlog_pos, master_connect_retry=1; start slave"

mysql-test/suite/xtrabackup/include/xb_setup_replication_gtid.sh

@@ -1,6 +1,6 @@
 set -e
 
-binlog_line=($(grep -m 1 -o "Last MySQL binlog file position 0 [0-9]*, file name .*\.[0-9]*" ${MYSQL_TMP_DIR}/xtrabackup_restore_log))
+binlog_line=($(grep -m 1 -o "Last MySQL binlog file position 0 [0-9]*, file name .*\.[0-9]*" ${MYSQLTEST_VARDIR}/log/xtrabackup_restore_log))
 binlog_pos=${binlog_line[6]%?}
 binlog_file=${binlog_line[9]}
 
@@ -17,4 +17,4 @@ sql="$sql stop slave;"
 sql="$sql change master to master_auto_position=0;"
 sql="$sql start slave;"
 $MYSQL --defaults-group-suffix=.2 -e "$sql"
-echo "$sql" > ${MYSQL_TMP_DIR}/gtid_stmt
+echo "$sql" > ${MYSQLTEST_VARDIR}/log/gtid_stmt

mysql-test/suite/xtrabackup/include/xb_xbstream_run.sh

@@ -7,6 +7,7 @@ defaults_file_opt="--defaults-file=${MYSQLTEST_VARDIR}/my.cnf"
 backup_dir="${MYSQLTEST_VARDIR}/backup"
 dest_data_dir="${MYSQLTEST_VARDIR}/mysqld.2/data/"
 xbstream_opt="--stream=${MYSQL_XBSTREAM}"
+log_dir="${MYSQLTEST_VARDIR}/log"
 
 mysql_dir=$(echo $MYSQL | awk '{print $1}' | xargs dirname)
 PATH=$mysql_dir:$PATH
@@ -18,24 +19,24 @@ rm -rf $dest_data_dir/
 mkdir $dest_data_dir
 
 echo "innobackupex copy phase"
-if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.1 $ibbackup_opt $xbstream_opt $backup_dir 2> ${MYSQL_TMP_DIR}/xtrabackup_copy_log | $MYSQL_XBSTREAM -x --directory=$backup_dir
+if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.1 $ibbackup_opt $xbstream_opt $backup_dir 2> $log_dir/xtrabackup_copy_log | $MYSQL_XBSTREAM -x --directory=$backup_dir
 then
-  tail ${MYSQL_TMP_DIR}/xtrabackup_copy_log
+  tail $log_dir/xtrabackup_copy_log
   exit 1
 fi
 mkdir ${backup_dir}/test      # TODO: Fix xbstream skipping empty directories
 
 echo "innobackupex apply-log phase"
-if ! $MYSQL_INNOBACKUPEX $ibbackup_opt $backup_dir --apply-log > ${MYSQL_TMP_DIR}/xtrabackup_restore_log 2>&1
+if ! $MYSQL_INNOBACKUPEX $ibbackup_opt $backup_dir --apply-log > $log_dir/xtrabackup_restore_log 2>&1
 then
-  tail ${MYSQL_TMP_DIR}/xtrabackup_restore_log
+  tail $log_dir/xtrabackup_restore_log
   exit 1
 fi
 
 echo "innobackupex move-back phase"
-if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.2 $ibbackup_opt $backup_dir --move-back > ${MYSQL_TMP_DIR}/xtrabackup_moveback_log 2>&1
+if ! $MYSQL_INNOBACKUPEX $defaults_file_opt --defaults-group=mysqld.2 $ibbackup_opt $backup_dir --move-back > $log_dir/xtrabackup_moveback_log 2>&1
 then
-  tail ${MYSQL_TMP_DIR}/xtrabackup_moveback_log
+  tail $log_dir/xtrabackup_moveback_log
   exit 1
 fi
 cp $backup_dir/ib_logfile* $dest_data_dir

storage/innobase/buf/buf0buf.cc

@@ -667,6 +667,16 @@ buf_page_is_corrupted(
 		/* Stored log sequence numbers at the start and the end
 		of page do not match */
 
+#ifdef XTRABACKUP
+			ut_print_timestamp(stderr);
+			fprintf(stderr,
+				" InnoDB (XtraBackup): Error:"
+				" Stored log sequence numbers\n"
+				"InnoDB (XtraBackup):"
+				" at the start and the end of page\n"
+				"InnoDB (XtraBackup): do not match");
+#endif /* XTRABACKUP */
+
 		return(TRUE);
 	}
 
@@ -764,11 +774,25 @@ FIL_PAGE_END_LSN_OLD_CHKSUM == 0 */
 			// computed checksums, *and* doesn't match against
 			// old_checksum, corrupt!  Otherwise, non-corrupt.
 			if (!fb_crc32_match(both_crcs, checksum_field1)
-			    && checksum_field1 != buf_calc_page_new_checksum(read_buf))
+			    && checksum_field1 != buf_calc_page_new_checksum(read_buf)) {
+#ifdef XTRABACKUP
+				ut_print_timestamp(stderr);
+				fprintf(stderr,
+					" InnoDB (XtraBackup): Error:"
+					" checksum_field1 does not match");
+#endif /* XTRABACKUP */
 				return (TRUE);
+			}
 			if (!fb_crc32_match(both_crcs, checksum_field2)
-			    && checksum_field2 != buf_calc_page_old_checksum(read_buf))
+			    && checksum_field2 != buf_calc_page_old_checksum(read_buf)) {
+#ifdef XTRABACKUP
+				ut_print_timestamp(stderr);
+				fprintf(stderr,
+					" InnoDB (XtraBackup): Error:"
+					" checksum_field2 does not match");
+#endif /* XTRABACKUP */
 				return (TRUE);
+			}
 			return (FALSE);
 		}
 

xtrabackup/src/xtrabackup.cc

@@ -2280,6 +2280,9 @@ xtrabackup_copy_datafile(fil_node_t* node, uint thread_n, ds_ctxt_t *ds_ctxt)
 						    "%s seems to be "
 						    "corrupted.\n",
 						    thread_n, node->name);
+						buf_page_print(page+chunk_offset,
+								info.zip_size,
+								BUF_PAGE_PRINT_NO_CRASH);
 						goto error;
 					}
 					msg("[%02u] xtrabackup: "