[MDEV-13416] mariabackup --backup fails to copy log if LSN is above 4294967295 Created: 2017-07-31  Updated: 2020-08-25  Resolved: 2017-08-11

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.2.7
Fix Version/s: 10.2.8

Type: Bug Priority: Major
Reporter: Hartmut Holzgraefe Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-13304 mariabackup 10.2.7 Errcode: 14 "Bad a... Closed
is duplicated by MDEV-13752 mariabackup Error Invalid argument Closed
Relates
relates to MDEV-14874 innodb_encrypt_log corrupts the log w... Closed

 Description   

On a potentially corrupted server instance mariabackup fails with errno 14 EFAULT - Bad Address

mariabackup --backup --user=root --password=... --target-dir=.../backup/$(date +\%Y-\%m-\%d_\%H:\%M:\%S) 
170728 15:56:46 Connecting to MySQL server host: localhost, user: root, password: set, port: 3306, socket: /var/run/mysqld/mysqld.sock
 
Using server version 10.2.7-MariaDB-10.2.7+maria~xenial-log
 
mariabackup based on MariaDB server 10.2.7-MariaDB Linux (x86_64)
 
xtrabackup: uses posix_fadvise().
 
xtrabackup: cd to /var/lib/mysql/
 
xtrabackup: open files limit requested 215200, set to 215200
 
xtrabackup: using the following InnoDB configuration:
 
xtrabackup: innodb_data_home_dir = .
 
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup: innodb_log_group_home_dir = ./
 
2017-07-28 15:56:46 140398601803584 [Note] InnoDB: Number of pools: 1
 
mariabackup: Error writing file '.../backup/2017-07-28_15:56:46/ib_logfile0' (Errcode: 14 "Bad address")
 
xtrabackup: Error: write to logfile failed
 
xtrabackup: Error: xtrabackup_copy_logfile() failed.

strace shows that after a few small reads from input file ib_logfile0 input file iblogfile1 is opened, 64KB are read from it, and an attempt to write ~18 ExaByte to the ib_logfile0 output file in the backup target dir is made.

mkdir("/mysqldepot/backup/2017-07-29_16:47:46/", 0700) = 0
 
open("./ib_logfile0", O_RDONLY)         = 4
 
pread64(4, "\0\0\0\1\0\0\0\0\0\0\ft\370\36\200\0MariaDB 10.2.7\0\0"..., 512, 0) = 512
 
pread64(4, "\0\0\0\0\0\4\373^\0\0\fx\237\1C\364\0\0\0\3\246\342\323\364\0\0\0\0\4\0\0\0"..., 512, 512) = 512
 
pread64(4, "\0\0\0\0\0\4\373_\0\0\fx\237\1D\r\0\0\0\3\246\342\324\r\0\0\0\0\4\0\0\0"..., 512, 1536) = 512
 
pread64(4, "\0\0\0\1\0\0\0\0\0\0\ft\370\36\200\0MariaDB 10.2.7\0\0"..., 512, 0) = 512
 
pread64(4, "\0\0\0\0\0\4\373^\0\0\fx\237\1C\364\0\0\0\3\246\342\323\364\0\0\0\0\4\0\0\0"..., 512, 512) = 512
 
pread64(4, "\0\0\0\0\0\4\373_\0\0\fx\237\1D\r\0\0\0\3\246\342\324\r\0\0\0\0\4\0\0\0"..., 512, 1536) = 512
 
mkdir("/mysqldepot/backup/2017-07-29_16:47:46/", 0700) = -1 EEXIST (File exists)
 
mkdir("/mysqldepot/backup/2017-07-29_16:47:46/", 0700) = -1 EEXIST (File exists)
 
open("/mysqldepot/backup/2017-07-29_16:47:46/ib_logfile0", O_WRONLY|O_CREAT|O_EXCL|O_NOFOLLOW, 0660) = 5
 
write(5, "\0\0\0\1\0\0\0\0\0\0\fx\237\1D\rBackup 10.2.7-Ma"..., 512) = 512
 
fadvise64(5, 0, 0, POSIX_FADV_DONTNEED) = 0
 
write(5, "\0\0\0\0\0\4\373_\0\0\fx\237\1D\r\0\0\0\0\0\0\10\r\0\0\0\0\4\0\0\0"..., 512) = 512
 
fadvise64(5, 0, 0, POSIX_FADV_DONTNEED) = 0
 
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
 
fadvise64(5, 0, 0, POSIX_FADV_DONTNEED) = 0
 
write(5, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
 
fadvise64(5, 0, 0, POSIX_FADV_DONTNEED) = 0
 
open("./ib_logfile1", O_RDONLY)         = 6
 
pread64(6, "\274O\200\243\0\26\0\r\0\4\373_\3648\0\0\fx\237\1D\r\0\0\0\0\0\0\0\0\0\0"..., 65536, 7094850560) = 65536
 
write(5, "\274O\200\243\0\26\0\r\0\4\373_\3648\0\0\fx\237\1D\r\0\0\0\0\0\0\0\0\0\0"..., 18446730364173942784) = -1 EFAULT (Bad address)
 
write(2, "\7", 1)                       = 1
 
write(2, "mariabackup", 11)             = 11
 
write(2, ": ", 2)                       = 2
 
write(2, "Error writing file '/mysqldepot/"..., 99) = 99
 
write(2, "\n", 1)                       = 1
 
write(2, "xtrabackup: Error: write to logf"..., 43) = 43

From looking at the error message text this seems to be happing in xtrabackup_scan_log_recs() in extra/mariabackup/xtrabackup.cc

So either we have something overwriting the write_size variable there, giving it an insanely large value, or the values read and used to calculate the write_size are already corrupted to begin with.

If the later is true the some sanity checks should be added to catch values that exceed innodb_log_file_size and report some more meaningful error message in that case ...

 Comments   
Comment by Hartmut Holzgraefe [ 2017-08-01 ]

We got strace output for two different systems running into this error now, one that had suffered from prior corruption, and one considered clean.

The write_size values in those two cases were 18446730364173942784 and 18446730346994073600, or in hex: 0xFFFF F388 0000 0000 and oxFFFF F384 0000 0000, so differing by exactly 0x4 0000 0000

Comment by Andrii Nikitin (Inactive) [ 2017-08-11 ]

The error is shown for instances with huge LSN

Steps to reproduce / confirm:
1. Install fresh data directory and start server
2. Increase LSN, eg. by attaching to the process with gdb :

set log_sys->lsn = 16000000000000

3. Restart server, make sure that new huge LSN is printed in Error log.
(you may need to remove old innodb logs if LSN is hacked with gdb command above)

2017-08-11 12:42:05 139786613155648 [Note] InnoDB: 5.7.18 started; log sequence number 16000000004620
 
...
 
Version: '10.2.7-MariaDB'  socket: '/test/mariadb-environs/m7-10.2.7/dt/my.sock'  port: 3313  MariaDB Server

4. Try to backup server using mariabackup 10.2.7 , observe error:

mariabackup --defaults-file=my.cnf --target-dir=bkup --backup
 
...
 
mariabackup: Error writing file '/test/mariadb-environs/m7-10.2.7/bkup/ib_logfile0' (Errcode: 14 "Bad address")
 
xtrabackup: Error: write to logfile failed
 
xtrabackup: Error: xtrabackup_copy_logfile() failed.

Comment by Marko Mäkelä [ 2017-08-11 ]

anikitin, please provide a mysql-test case for this. Here is a start for it:

--source include/not_embedded.inc
 
 
 
--echo #
 
--echo # MDEV-13416 mariabackup fails with EFAULT "Bad Address"
 
--echo #
 
 
 
let INNODB_PAGE_SIZE=`select @@innodb_page_size`;
 
let MYSQLD_DATADIR=`select @@datadir`;
 
 
 
--source include/shutdown_mysqld.inc
 
 
 
perl;
 
my $file= "$ENV{MYSQLD_DATADIR}/ibdata1";
 
open(FILE, "+<", $file) or die "Unable to open $file\n";
 
binmode FILE;
 
my $ps= $ENV{INNODB_PAGE_SIZE};
 
my $page;
 
die "Unable to read $file" unless sysread(FILE, $page, $ps) == $ps;
 
substr($page,26,8) = pack("NN", 4096, 0);
 
substr($page,0,4)=pack("N",0xdeadbeef);
 
substr($page,$ps-8,4)=pack("N",0xdeadbeef);
 
sysseek(FILE, 0, 0) || die "Unable to rewind $file\n";
 
syswrite(FILE, $page, $ps)==$ps || die "Unable to write $file\n";
 
close(FILE) || die "Unable to close $file\n";
 
EOF
 
 
 
--remove_files_wildcard $MYSQLD_DATADIR ib_logfile*
 
 
 
--source include/start_mysqld.inc
 
let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
 
--let SEARCH_PATTERN= InnoDB: 5\.7\.\d+ started; log sequence number 17592186044428
 
--source include/search_pattern_in_file.inc

Please augment the test so that it will invoke xtrabackup and reproduce the failure.

Comment by Andrii Nikitin (Inactive) [ 2017-08-11 ]

following test demonstrates the problem:

(14:52 mysql-test) > ls */*/huge_lsn.test
 
suite/mariabackup/huge_lsn.test
 
(14:56 mysql-test) > cat */*/huge_lsn.test
 
--source include/not_embedded.inc
 
 
 
--echo #
 
--echo # MDEV-13416 mariabackup fails with EFAULT "Bad Address"
 
--echo #
 
 
 
let INNODB_PAGE_SIZE=`select @@innodb_page_size`;
 
let MYSQLD_DATADIR=`select @@datadir`;
 
 
 
--source include/shutdown_mysqld.inc
 
perl;
 
my $file= "$ENV{MYSQLD_DATADIR}/ibdata1";
 
open(FILE, "+<", $file) or die "Unable to open $file\n";
 
binmode FILE;
 
my $ps= $ENV{INNODB_PAGE_SIZE};
 
my $page;
 
die "Unable to read $file" unless sysread(FILE, $page, $ps) == $ps;
 
substr($page,26,8) = pack("NN", 4096, 0);
 
substr($page,0,4)=pack("N",0xdeadbeef);
 
substr($page,$ps-8,4)=pack("N",0xdeadbeef);
 
sysseek(FILE, 0, 0) || die "Unable to rewind $file\n";
 
syswrite(FILE, $page, $ps)==$ps || die "Unable to write $file\n";
 
close(FILE) || die "Unable to close $file\n";
 
EOF
 
 
 
--remove_files_wildcard $MYSQLD_DATADIR ib_logfile*
 
 
 
--source include/start_mysqld.inc
 
let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
 
--let SEARCH_PATTERN= InnoDB: 5\.7\.\d+ started; log sequence number 17592186044428
 
--source include/search_pattern_in_file.inc
 
 
 
 
 
CREATE TABLE t(i INT) ENGINE INNODB;
 
INSERT INTO t VALUES(1);
 
echo # xtrabackup backup;
 
let $targetdir=$MYSQLTEST_VARDIR/tmp/backup;
 
 
 
--disable_result_log
 
exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir;
 
--enable_result_log
 
 
 
INSERT INTO t VALUES(2);
 
 
 
 
 
echo # xtrabackup prepare;
 
--disable_result_log
 
exec $XTRABACKUP  --prepare --target-dir=$targetdir;
 
-- source include/restart_and_restore.inc
 
--enable_result_log
 
 
 
SELECT * FROM t;
 
DROP TABLE t;
 
rmdir $targetdir;
 
 
 
(14:56 mysql-test) > ./mtr huge_lsn
 
Logging: ./mtr  huge_lsn
 
vardir: /home/a/spd/_depot/m-tar/10.2.7/mysql-test/var
 
Checking leftover processes...
 
Removing old var directory...
 
Creating var directory '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var'...
 
Checking supported features...
 
MariaDB Version 10.2.7-MariaDB
 
 - SSL connections supported
 
Collecting tests...
 
Installing system database...
 
 
 
==============================================================================
 
 
 
TEST                                      RESULT   TIME (ms) or COMMENT
 
--------------------------------------------------------------------------
 
 
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
 
#
 
# MDEV-13416 mariabackup fails with EFAULT "Bad Address"
 
#
 
FOUND 1 /InnoDB: 5\.7\.\d+ started; log sequence number 17592186044428/ in mysqld.1.err
 
CREATE TABLE t(i INT) ENGINE INNODB;
 
INSERT INTO t VALUES(1);
 
# xtrabackup backup
 
mariabackup.huge_lsn                     [ fail ]
 
        Test ended at 2017-08-11 14:56:43
 
 
 
CURRENT_TEST: mariabackup.huge_lsn
 
mysqltest: At line 40: exec of '/home/a/spd/_depot/m-tar/10.2.7/bin/mariabackup --defaults-file=/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/my.cnf --backup --target-dir=/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/tmp/backup 2>&1' failed, error: 256, status: 1, errno: 11
 
Output from before failure:
 
170811 14:56:43 Connecting to MySQL server host: localhost, user: root, password: set, port: 16000, socket: /home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/tmp/mysqld.1.sock
 
Using server version 10.2.7-MariaDB-log
 
/home/a/spd/_depot/m-tar/10.2.7/bin/mariabackup based on MariaDB server 10.2.7-MariaDB Linux (x86_64) 
xtrabackup: uses posix_fadvise().
 
xtrabackup: cd to /home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/mysqld.1/data/
 
xtrabackup: open files limit requested 1024, set to 1024
 
xtrabackup: using the following InnoDB configuration:
 
xtrabackup:   innodb_data_home_dir = .
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
2017-08-11 14:56:43 140457059727168 [Note] InnoDB: Number of pools: 1
 
/home/a/spd/_depot/m-tar/10.2.7/bin/mariabackup: Error writing file '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/tmp/backup/ib_logfile0' (Errcode: 14 "Bad address")
 
xtrabackup: Error: write to logfile failed
 
xtrabackup: Error: xtrabackup_copy_logfile() failed.
 
 
 
 - saving '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/log/mariabackup.huge_lsn/' to '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/log/mariabackup.huge_lsn/'
 
--------------------------------------------------------------------------
 
The servers were restarted 0 times
 
Spent 0.000 of 8 seconds executing testcases
 
 
 
Failure: Failed 1/1 tests, 0.00% were successful.
 
 
 
Failing test(s): mariabackup.huge_lsn
 
 
 
The log files in var/log may give you some hint of what went wrong.
 
 
 
If you want to report this error, please read first the documentation
 
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
 
 
mysql-test-run: *** ERROR: there were failing test cases

Generated at Thu Feb 08 08:05:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.