[MDEV-12108] mariabackup doesn't handle table's DATA DIRECTORY clause Created: 2017-02-22  Updated: 2017-11-08  Resolved: 2017-11-08

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.1.22, 10.1.25, 10.2.7
Fix Version/s: 10.1.29, 10.2.11

Type: Bug Priority: Major
Reporter: Andrii Nikitin (Inactive) Assignee: Vladislav Vaintroub
Resolution: Fixed Votes: 0
Labels: None

Attachments: File mtr.log    
Sprint: 10.2.10, 10.1.29

 Description   

Observed new xtrabackup crash during prepare in bb-10.1-wlad-xtrabackup after recent merge (I have strong consideration that it didn't crash in source code from ~December).

InnoDB: Tablespaces for test/test#P#p2 have been found in two places;
Location 1: SpaceID: 6  LSN: 0  File: ./test/test#P#p2.ibd
Location 2: SpaceID: 6  LSN: 0  File: /home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/mysql-test/var/partitdata/test/test#P#p2.ibd
You must delete one of them.
170222  9:24:34 [ERROR] mysqld got signal 6 ;
...
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/extra/xtrabackup/xtrabackup(my_print_stacktrace+0x29)[0x55f6d8034149]
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/extra/xtrabackup/xtrabackup(handle_fatal_signal+0x3ad)[0x55f6d7c1cfed]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11630)[0x7fc71f7e6630]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x9f)[0x7fc71dc767ef]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fc71dc783ea]
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/extra/xtrabackup/xtrabackup(+0x847204)[0x55f6d7eb7204]
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/extra/xtrabackup/xtrabackup(+0x8ce1b4)[0x55f6d7f3e1b4]
mysys/stacktrace.c:268(my_print_stacktrace)[0x55f6d7f42d11]
sql/signal_handler.cc:168(handle_fatal_signal)[0x55f6d7f437a4]
log/log0recv.cc:3088(recv_init_crash_recovery())[0x55f6d7f43e9a]
srv/srv0start.cc:2529(innobase_start_or_create_for_mysql())[0x55f6d7fbf3f6]
xtrabackup/xtrabackup.cc:1842(innodb_init())[0x55f6d79d857d]
xtrabackup/xtrabackup.cc:6336(xtrabackup_prepare_func)[0x55f6d79e4ffc]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)[0x7fc71dc613f1]
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/extra/xtrabackup/xtrabackup(_start+0x2a)[0x55f6d79f893a]

Please note that indeed .ibd file exists in both places, just it is probably valid situation as one of places is actual original .ibd referenced by .isl inside backup:

$ find ~/farm/m9-bb-10.1-wlad-xtrabackup/build/mysql-test/var/ | grep p2.i
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/mysql-test/var/log/xtrabackup.partition_data_external/mysqld.1/data/test/test#P#p2.isl
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/mysql-test/var/backup/test/test#P#p2.ibd
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/mysql-test/var/backup/test/test#P#p2.isl
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/mysql-test/var/partitdata/test/test#P#p2.ibd

Test case run with :

perl mysql-test-run.pl --mysqld="--partition" partition_data_external.test

$ cat ../mysql-test/suite/xtrabackup/partition_data_external.test 
let $targetdir=$MYSQLTEST_VARDIR/backup;
mkdir $targetdir;
mkdir $MYSQLTEST_VARDIR/partitdata;
eval CREATE TABLE test (
  a int(11) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1
PARTITION BY RANGE (a)
(PARTITION p0 VALUES LESS THAN (100),
 PARTITION P1 VALUES LESS THAN (200),
 PARTITION p2 VALUES LESS THAN (300)
   DATA DIRECTORY = "$MYSQLTEST_VARDIR/partitdata",
 PARTITION p3 VALUES LESS THAN (400)
   DATA DIRECTORY = "$MYSQLTEST_VARDIR/partitdata",
 PARTITION p4 VALUES LESS THAN MAXVALUE);
INSERT INTO test VALUES (1), (101), (201), (301), (401);
exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup  --target-dir=$targetdir;
exec $XTRABACKUP --prepare --target-dir=$targetdir;
DROP TABLE t;
rmdir $targetdir;
rmdir $MYSQLTEST_VARDIR/partitdata;



 Comments   
Comment by Andrii Nikitin (Inactive) [ 2017-02-22 ]

Note1 : xtrabackup mtr test suite has been renamed to mariabackup , so need adjust paths above accordingly.
Note2 : stack trace with ha_innodb.so has little more info showing that crash happens in fil_load_single_table_tablespaces:

mysys/stacktrace.c:268(my_print_stacktrace)[0x7f22903a73ea]
fil/fil0fil.cc:5513(fil_load_single_table_tablespaces(unsigned long (*)(char const*, char const*)))[0x56176c1e9204]
log/log0recv.cc:3088(recv_init_crash_recovery())[0x56176c2701b4]
log/log0recv.cc:2898(recv_scan_log_recs(unsigned long, unsigned long, unsigned char const*, unsigned long, unsigned long, unsigned long*, unsigned long*, dberr_t*))[0x56176c274d11]
log/log0recv.cc:3031(recv_group_scan_log_recs(log_group_t*, unsigned long*, unsigned long*, dberr_t*))[0x56176c2757a4]
log/log0recv.cc:3328(recv_recovery_from_checkpoint_start_func(unsigned long, unsigned long, unsigned long, unsigned long))[0x56176c275e9a]
srv/srv0start.cc:2529(innobase_start_or_create_for_mysql())[0x56176c2f13f6]
xtrabackup/xtrabackup.cc:1842(innodb_init())[0x56176bd0a57d]
xtrabackup/xtrabackup.cc:6336(xtrabackup_prepare_func)[0x56176bd16ffc]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)[0x7f22903903f1]
/home/a/farm/m9-bb-10.1-wlad-xtrabackup/build/extra/xtrabackup//xtrabackup(_start+0x2a)[0x56176bd2a93a]

Following assert in fil_extend_space_to_desired_size() triggers:

                fil_space_t* space = fil_space_get_by_id(space_id);
                ut_a(space);

Comment by Andrii Nikitin (Inactive) [ 2017-07-12 ]

10.2 is affected as well .
Following test asserts in 10.1.25 and produces incorrect result with 10.2.7 (only one row should present in output after restore):

test case

--replace_result $MYSQL_TMP_DIR MYSQL_TMP_DIR
EVAL CREATE TABLE t(a INT) ENGINE=InnoDB, DATA DIRECTORY='$MYSQL_TMP_DIR';
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);
 
--source include/shutdown_mysqld.inc
 
echo # xtrabackup prepare;
--disable_result_log
exec $XTRABACKUP  --prepare --target-dir=$targetdir;
--source include/start_mysqld.inc
-- source include/restart_and_restore.inc
--enable_result_log
 
SELECT * FROM t;
DROP TABLE t;
rmdir $targetdir;

10.2 (incorrect number of rows after restore - should be only 1):

bash-4.2$ ./mtr remote_tablespace
Logging: /home/a/spd/_depot/m-branch/10.2/mysql-test/mysql-test-run.pl  remote_tablespace
vardir: /home/a/spd/m0-10.2/build/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/a/spd/m0-10.2/build/mysql-test/var'...
Checking supported features...
MariaDB Version 10.2.8-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
CREATE TABLE t(a INT) ENGINE=InnoDB, DATA DIRECTORY='MYSQL_TMP_DIR';
INSERT INTO t VALUES(1);
# xtrabackup backup
INSERT INTO t VALUES(2);
# xtrabackup prepare
# shutdown server
# remove datadir
# xtrabackup move back
# restart server
SELECT * FROM t;
a
1
2
DROP TABLE t;
mariabackup.remote_tablespace            [ pass ]   8640
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 8.640 of 14 seconds executing testcases
 
Completed: All 1 tests were successful.

10.1 shows already known assert "Tablespaces for {} have been found in two places"

bash-4.2$ ./mtr remote_tablespace
Logging: ./mtr  remote_tablespace
vardir: /home/a/spd/_depot/m-tar/10.1.25/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/a/spd/_depot/m-tar/10.1.25/mysql-test/var'...
Checking supported features...
MariaDB Version 10.1.25-MariaDB
 - SSL connections supported
Sphinx 'indexer' binary not found, sphinx suite will be skipped
Collecting tests...
Installing system database...
 
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
CREATE TABLE t(a INT) ENGINE=InnoDB, DATA DIRECTORY='MYSQL_TMP_DIR';
INSERT INTO t VALUES(1);
# xtrabackup backup
INSERT INTO t VALUES(2);
# xtrabackup prepare
mariabackup.remote_tablespace            [ fail ]
        Test ended at 2017-07-12 22:09:12
 
CURRENT_TEST: mariabackup.remote_tablespace
sh: line 1: 22945 Aborted                 (core dumped) /home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup --prepare --target-dir=/home/a/spd/_depot/m-tar/10.1.25/mysql-test/var/tmp/backup 2>&1
mysqltest: At line 17: exec of '/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup  --prepare --target-dir=/home/a/spd/_depot/m-tar/10.1.25/mysql-test/var/tmp/backup 2>&1' failed, error: 34304, status: 134, errno: 0
Output from before failure:
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup based on MariaDB server 10.1.25-MariaDB Linux (x86_64) 
xtrabackup: cd to /home/a/spd/_depot/m-tar/10.1.25/mysql-test/var/tmp/backup/
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(1629556)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 1
xtrabackup:   innodb_log_file_size = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 1
xtrabackup:   innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using mutexes to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Using SSE crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Starting crash recovery from checkpoint LSN=1629556
InnoDB: Tablespaces for test/t have been found in two places;
Location 1: SpaceID: 4 File: ./test/t.ibd
Location 2: SpaceID: 4 File: /home/a/spd/_depot/m-tar/10.1.25/mysql-test/var/tmp/test/t.ibd
You must delete one of them.
170712 22:09:07 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.1.25-MariaDB
key_buffer_size=0
read_buffer_size=131072
max_used_connections=0
max_threads=1
thread_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5301 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x48400
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup(my_print_stacktrace+0x2e)[0xc387ce]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup(handle_fatal_signal+0x4bf)[0x79959f]
/lib64/libpthread.so.0(+0xf370)[0x7fc8dc3c2370]
/lib64/libc.so.6(gsignal+0x37)[0x7fc8db1d71d7]
/lib64/libc.so.6(abort+0x148)[0x7fc8db1d88c8]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0x98404e]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0x984680]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0xa13690]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0xa18fe4]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0xa19fb9]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0xa9c6c8]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0x524b30]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup(main+0x747)[0x528397]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7fc8db1c3b35]
/home/a/spd/_depot/m-tar/10.1.25/bin/mariabackup[0x51caa9]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
 
 - saving '/home/a/spd/_depot/m-tar/10.1.25/mysql-test/var/log/mariabackup.remote_tablespace/' to '/home/a/spd/_depot/m-tar/10.1.25/mysql-test/var/log/mariabackup.remote_tablespace/'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 15 seconds executing testcases
 
Failure: Failed 1/1 tests, 0.00% were successful.
 
Failing test(s): mariabackup.remote_tablespace
 
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

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

I pushed the merge to 10.2. It required an additional change to the interpretation of MLOG_FILE_NAME records that were introduced in 10.2.2 by the merge of MySQL 5.7.9.
I am rather sure that ALTER/RENAME/TRUNCATE TABLE operations would cause trouble. So, it is safest to use the MDEV-13825 option --lock-ddl-per-table.

Generated at Thu Feb 08 07:55:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.