[MDEV-15988] Crash in ./mtr mariabackup.undo_space_id Created: 2018-04-23  Updated: 2018-04-24  Resolved: 2018-04-24

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.1.32, 10.2.14, 10.3.6
Fix Version/s: 10.1.33, 10.2.15, 10.3.7

Type: Bug Priority: Major
Reporter: Alexander Barkov Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression

Issue Links:
Problem/Incident
is caused by MDEV-13561 Mariabackup is incompatible with retr... Closed

 Description   

I built the server as follows (using the same binary directory and source directory):

cmake . -DCMAKE_BUILD_TYPE=Debug -DCMAKE_INSTALL_PREFIX=/opt/mariadb-10.3 -DSECURITY_HARDENED=0

The test mariabackup.undo_space_id crashes.

mariabackup.undo_space_id 'innodb'       [ fail ]
        Test ended at 2018-04-23 18:34:56
 
CURRENT_TEST: mariabackup.undo_space_id
sh: line 1:  6988 Aborted                 (core dumped) /home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup --defaults-file=/home/bar/maria-git/server.10.3/mysql-test/var/my.cnf --backup --target-dir=/home/bar/maria-git/server.10.3/mysql-test/var/tmp/backup 2>&1
mysqltest: At line 14: exec of '/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup --defaults-file=/home/bar/maria-git/server.10.3/mysql-test/var/my.cnf  --backup --target-dir=/home/bar/maria-git/server.10.3/mysql-test/var/tmp/backup 2>&1' failed, error: 34304, status: 134, errno: 11
Output from before failure:
180423 18:34:55 Connecting to MySQL server host: localhost, user: root, password: set, port: 16000, socket: /home/bar/maria-git/server.10.3/mysql-test/var/tmp/mysqld.1.sock
Using server version 10.3.7-MariaDB-debug-log
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup based on MariaDB server 10.3.7-MariaDB Linux (x86_64) 
mariabackup: uses posix_fadvise().
mariabackup: cd to /home/bar/maria-git/server.10.3/mysql-test/var/mysqld.1/data/
mariabackup: open files limit requested 1024, set to 1024
mariabackup: using the following InnoDB configuration:
mariabackup:   innodb_data_home_dir = 
mariabackup:   innodb_data_file_path = ibdata1:12M:autoextend
mariabackup:   innodb_log_group_home_dir = ./
2018-04-23 18:34:55 0 [Note] InnoDB: Number of pools: 1
2018-04-23 18:34:55 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-04-23 18:34:55 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-04-23 18:34:55 0 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2018-04-23 18:34:55 0 [ERROR] InnoDB: File ibdata: 'open' returned OS error 71. Cannot continue operation
180423 18:34:55 [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.3.7-MariaDB-debug
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 = 5669 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 0x49000
log/log0log.cc:1143(log_write_up_to(unsigned long, bool))[0x11da3f7]
sql/keycaches.cc:233(_GLOBAL__sub_I_keycaches.cc)[0xaeac17]
sigaction.c:0(__restore_rt)[0x7f65450d4a00]
linux/raise.c:55(__GI_raise)[0x7f6543348a28]
stdlib/abort.c:91(__GI_abort)[0x7f654334a62a]
sql/sql_type.cc:3286(Type_handler_real_result::Item_val_int_signed_typecast(Item*) const)[0xdfdb34]
sql/sql_type.cc:1352(Type_handler_varchar::make_conversion_table_field(TABLE*, unsigned int, Field const*) const)[0xdf98ad]
sql/sql_type.cc:2368(Type_handler_blob::make_table_field(st_mysql_const_lex_string const*, Record_addr const&, Type_all_attributes const&, TABLE*) const)[0xdfbd71]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup[0x648a80]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup[0x64dd1c]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup[0x64e04e]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup[0x650008]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup[0x654554]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup(main+0x246)[0x653dd8]
csu/libc-start.c:323(__libc_start_main)[0x7f6543334580]
/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup(_start+0x29)[0x647919]
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.
 
 
 
The result from queries just before the failure was:
# Create 2 UNDO TABLESPACE(UNDO003, UNDO004)
CREATE TABLE t1(a varchar(60)) ENGINE INNODB;
start transaction;
INSERT INTO t1 VALUES(1);
# xtrabackup backup
 
 - saving '/home/bar/maria-git/server.10.3/mysql-test/var/log/mariabackup.undo_space_id-innodb/' to '/home/bar/maria-git/server.10.3/mysql-test/var/log/mariabackup.undo_space_id-innodb/'
 - found 'core.6988' (0/5)
 
Trying 'dbx' to get a backtrace
 
Trying 'gdb' to get a backtrace from coredump /home/bar/maria-git/server.10.3/mysql-test/var/log/mariabackup.undo_space_id-innodb/mysqld.1/data/core.6988
Core generated by '/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New LWP 6988]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/home/bar/maria-git/server.10.3/extra/mariabackup/mariabackup --defaults-file=/'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f6543348d67 in kill () at ../sysdeps/unix/syscall-template.S:84
84	T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
#0  0x00007f6543348d67 in kill () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000000aeb008 in handle_fatal_signal (sig=6) at /home/bar/maria-git/server.10.3/sql/signal_handler.cc:317
#2  <signal handler called>
#3  0x00007f6543348a28 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
#4  0x00007f654334a62a in __GI_abort () at abort.c:89
#5  0x0000000000dfdb34 in os_file_handle_error_cond_exit (name=0x7ffdcc164370 "ibdata", operation=0x14e9e69 "open", should_abort=true, on_error_silent=false) at /home/bar/maria-git/server.10.3/storage/innobase/os/os0file.cc:5184
#6  0x0000000000df98ad in os_file_handle_error (name=0x7ffdcc164370 "ibdata", operation=0x14e9e69 "open") at /home/bar/maria-git/server.10.3/storage/innobase/os/os0file.cc:736
#7  0x0000000000dfbd71 in os_file_create_func (name=0x7ffdcc164370 "ibdata", create_mode=51, purpose=62, type=100, read_only=true, success=0x7ffdcc16435f) at /home/bar/maria-git/server.10.3/storage/innobase/os/os0file.cc:3011
#8  0x0000000000648a80 in pfs_os_file_create_func (key=0, name=0x7ffdcc164370 "ibdata", create_mode=51, purpose=62, type=100, read_only=true, success=0x7ffdcc16435f, src_file=0x126d440 "/home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc", src_line=3057) at /home/bar/maria-git/server.10.3/storage/innobase/include/os0file.ic:170
#9  0x000000000064dd1c in xb_assign_undo_space_start () at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:3057
#10 0x000000000064e04e in xb_load_tablespaces () at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:3136
#11 0x0000000000650008 in xtrabackup_backup_func () at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:4067
#12 0x0000000000654554 in main_low (argv=0x45293b8) at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:5740
#13 0x0000000000653dd8 in main (argc=4, argv=0x7ffdcc1653b8) at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:5539
 
Thread 1 (Thread 0x7f65454d0840 (LWP 6988)):
#0  0x00007f6543348d67 in kill () at ../sysdeps/unix/syscall-template.S:84
#1  0x0000000000aeb008 in handle_fatal_signal (sig=6) at /home/bar/maria-git/server.10.3/sql/signal_handler.cc:317
#2  <signal handler called>
#3  0x00007f6543348a28 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
#4  0x00007f654334a62a in __GI_abort () at abort.c:89
#5  0x0000000000dfdb34 in os_file_handle_error_cond_exit (name=0x7ffdcc164370 "ibdata", operation=0x14e9e69 "open", should_abort=true, on_error_silent=false) at /home/bar/maria-git/server.10.3/storage/innobase/os/os0file.cc:5184
#6  0x0000000000df98ad in os_file_handle_error (name=0x7ffdcc164370 "ibdata", operation=0x14e9e69 "open") at /home/bar/maria-git/server.10.3/storage/innobase/os/os0file.cc:736
#7  0x0000000000dfbd71 in os_file_create_func (name=0x7ffdcc164370 "ibdata", create_mode=51, purpose=62, type=100, read_only=true, success=0x7ffdcc16435f) at /home/bar/maria-git/server.10.3/storage/innobase/os/os0file.cc:3011
#8  0x0000000000648a80 in pfs_os_file_create_func (key=0, name=0x7ffdcc164370 "ibdata", create_mode=51, purpose=62, type=100, read_only=true, success=0x7ffdcc16435f, src_file=0x126d440 "/home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc", src_line=3057) at /home/bar/maria-git/server.10.3/storage/innobase/include/os0file.ic:170
#9  0x000000000064dd1c in xb_assign_undo_space_start () at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:3057
#10 0x000000000064e04e in xb_load_tablespaces () at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:3136
#11 0x0000000000650008 in xtrabackup_backup_func () at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:4067
#12 0x0000000000654554 in main_low (argv=0x45293b8) at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:5740
#13 0x0000000000653dd8 in main (argc=4, argv=0x7ffdcc1653b8) at /home/bar/maria-git/server.10.3/extra/mariabackup/xtrabackup.cc:5539



 Comments   
Comment by Marko Mäkelä [ 2018-04-23 ]

I can repeat this (using gcc 8.0.1 and the provided build options). With my normal compilation options, the test passes.
I tried to debug this with a small patch:

diff --git a/mysql-test/suite/mariabackup/undo_space_id.test b/mysql-test/suite/mariabackup/undo_space_id.test
index 8adeb18e5a7..52ef5f67d54 100644
--- a/mysql-test/suite/mariabackup/undo_space_id.test
+++ b/mysql-test/suite/mariabackup/undo_space_id.test
@@ -11,7 +11,7 @@ INSERT INTO t1 VALUES(1);
 
 --echo # xtrabackup backup
 --disable_result_log
-exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --target-dir=$basedir;
+exec strace $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --target-dir=$basedir;
 --enable_result_log
 --echo # Display undo log files from target directory
 list_files $basedir undo*;

The full strace output would be in mysql-test/var/log/mysqltest.log. Here is the interesting part:

mariabackup 10.3 8fce4065e542ad64438d45f60421241dd383815f

stat("ibdata1", {st_mode=S_IFREG|0660, st_size=12582912, ...}) = 0
access("ibdata1", R_OK)                 = 0
openat(AT_FDCWD, "ibdata1", O_RDONLY)   = 9
fstat(9, {st_mode=S_IFREG|0660, st_size=12582912, ...}) = 0
mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f63f657a000
pread64(9, "A (4\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\26\253\17\0\10\0\0\0\0\0\27"..., 65536, 0) = 65536
close(9)                                = 0
openat(AT_FDCWD, "ibdata", O_RDONLY)    = -1 ENOENT (No such file or directory)
write(2, "2018-04-23 17:40:06 0 [ERROR] In"..., 912018-04-23 17:40:06 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.

InnoDB (or mariabackup) really should just open the file once, and avoid the stat() and access() calls.

To debug this further, I would suggest adding a sleep to the test before the exec and running mariabackup manually in gdb.

Comment by Marko Mäkelä [ 2018-04-23 ]

thiru noticed that the file name was truncated. Here is the fix:

diff --git a/extra/mariabackup/xtrabackup.cc b/extra/mariabackup/xtrabackup.cc
index a8b7022b948..b1047830c30 100644
--- a/extra/mariabackup/xtrabackup.cc
+++ b/extra/mariabackup/xtrabackup.cc
@@ -3050,7 +3050,7 @@ static dberr_t xb_assign_undo_space_start()
 		name[dirnamelen++] = OS_PATH_SEPARATOR;
 	}
 
-	snprintf(name + dirnamelen, strlen(name) + strlen("ibdata1"),
+	snprintf(name + dirnamelen, (sizeof name) - dirnamelen,
 		 "%s", "ibdata1");
 
 	file = os_file_create(0, name, OS_FILE_OPEN,

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