Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2.7
-
None
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 ...
Attachments
Issue Links
- is duplicated by
-
-
- Closed
-
-
-
- Closed
-
- relates to
-
-
- Closed
-
Activity
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.
|
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.
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 |
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