[MDEV-11483] Crash getByteOrder@SHA512 during restore of encrypted backup with FULLTEXT Created: 2016-12-05  Updated: 2016-12-08  Resolved: 2016-12-08

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: None
Fix Version/s: N/A

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

Attachments: File FTS_0000000000000014_000000000000001e_INDEX_6.ibd    

 Description   

I am getting following crash occasionally while restore encrypted backup with (empty) FULLTEXT index:

161205 11:52:04 [01] Copying ./test/film_text.ibd to F:/git/mysql-test/var/tmp/backup/test/film_text.ibd
161205 11:52:04 [01] ...done
161205 11:52:04 [01] Copying ./test/fts_0000000000000014_000000000000001e_index_1.ibd to F:/git/mysql-test/var/tmp/backup/test/fts_0000000000000014_000000000000001e_index_1.ibd
161205 11:52:04 [01] ...done
161205 11:52:04 [01] Copying ./test/fts_0000000000000014_000000000000001e_index_2.ibd to F:/git/mysql-test/var/tmp/backup/test/fts_0000000000000014_000000000000001e_index_2.ibd
161205 11:52:04 [01] ...done
161205 11:52:04 [01] Copying ./test/fts_0000000000000014_000161205 11:52:04 [ERROR] mysqld got exception 0x80000003 ;
...
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
ucrtbase.DLL!abort()
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
xtrabackup.exe!?getByteOrder@SHA512@TaoCrypt@@UBE?AW4ByteOrder@2@XZ()
KERNEL32.DLL!BaseThreadInitThunk()
ntdll.dll!RtlInitializeExceptionChain()
ntdll.dll!RtlInitializeExceptionChain()

Mtr test below reproduces the problem (I added two more FULLTEXT indexes to increase chance of crash, but it crashes with single first index as well - just with smaller probability):

.opt file:
--plugin-load-add=$FILE_KEY_MANAGEMENT_SO
--innodb_strict_mode
--innodb_file_per_table
--innodb-encrypt-log=ON
--innodb-encryption-rotate-key-age=2
--innodb-encryption-threads=4
--innodb-tablespaces-encryption
--innodb-encrypt-tables=FORCE
--loose-file-key-management
--loose-file-key-management-filename=$MYSQL_TEST_DIR/std_data/logkey.txt

.test file:

CREATE TABLE film_text (
film_id SMALLINT NOT NULL,
title VARCHAR(255) NOT NULL,
description TEXT,
PRIMARY KEY (film_id),
FULLTEXT KEY idx_title_description (title,description),
FULLTEXT KEY (description),
FULLTEXT KEY (title)
)ENGINE=InnoDB DEFAULT CHARSET=utf8;

let $targetdir=$MYSQLTEST_VARDIR/tmp/backup;
exec $XTRABACKUP --innobackupex --defaults-file=$MYSQLTEST_VARDIR/my.cnf --no-timestamp $targetdir;

exec $XTRABACKUP --innobackupex --apply-log --rebuild-indexes --rebuild-threads=2 $targetdir;
– source include/restart_and_restore.inc



 Comments   
Comment by Vladislav Vaintroub [ 2016-12-06 ]

tried hard to reproduce, failed with mysql-test-run --repeat=100 (either debug or release)

If you can add more data to the test to make it better reproducible, this would e much appreciated.

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

Definitely some timing issues are invovled here. When I put `sleep 1` before backup creation or start debugger - no crash happens. I was able to reproduce some crash on Ubuntu, just by creating 9 tables tables with 3 fulltext indexes each and starting backup immediately afterward:

InnoDB: Error: trying to access page number 0 in space 54,
InnoDB: space name test/FTS_0000000000000044_DELETED_CACHE,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
2016-12-06 19:51:48 7fe387fff700 InnoDB: Assertion failure in thread 140615216002816 in file fil0fil.cc line 6265

Comment by Vladislav Vaintroub [ 2016-12-07 ]

how large is the FTS_0000000000000044_DELETED_CACHE.idb file your var/mysqld.1/data/test after the crash?

Comment by Vladislav Vaintroub [ 2016-12-07 ]

maybe you can attach this file to the report.

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

I've realized that for some reasons debugging info was not enabled in 'Debug' configuration. After manual changing of corresponding compiling and linking options - the stack trace on windows looks like this:

xtrabackup.exe!__my_thread_var()
ucrtbase.DLL!raise()
ucrtbase.DLL!abort()
xtrabackup.exe!_fil_io()[fil0fil.cc:6233]
xtrabackup.exe!fil_space_get_crypt_data()[fil0fil.cc:7638]
xtrabackup.exe!buf_page_is_corrupted()[buf0buf.cc:724]
xtrabackup.exe!xb_fil_cur_read()[fil_cur.cc:349]
xtrabackup.exe!xtrabackup_copy_datafile()[xtrabackup.cc:2418]
xtrabackup.exe!data_copy_thread_func()[xtrabackup.cc:2934]

Debugger stops on following line and assert triggers inside fil_node_prepare_for_io because space = NULL
/* Open file if closed */
if (!fil_node_prepare_for_io(node, fil_system, space)) {

I couldn't get anything useful from other threads - they seem sleeping or waiting on mutex

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

This time crash was on different file, I am attaching it:
161207 11:43:40 [01] Copying .\test\fts_0000000000000014_000000000000001e_index_6.ibd to F:\git\mysql-test\var\tmp\backup\test\fts_0000000000000014_000000000000001e_index_6.ibd
InnoDB: Error: trying to access page number 0 in space 15,
InnoDB: space name test/FTS_0000000000000014_000000000000001e_INDEX_6,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
2016-12-07 11:43:40 194c InnoDB: Assertion failure in thread 6476 in file fil0fil.cc line 6265

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

Attached file is in source datadir, but in target directory problem file is really 0 size:

rw-rr- 1 Andrii 197609 114688 Dec 7 11:43 film_text.ibd
rw-rr- 1 Andrii 197609 98304 Dec 7 11:43 fts_0000000000000014_000000000000001e_index_1.ibd
rw-rr- 1 Andrii 197609 98304 Dec 7 11:43 fts_0000000000000014_000000000000001e_index_2.ibd
rw-rr- 1 Andrii 197609 98304 Dec 7 11:43 fts_0000000000000014_000000000000001e_index_3.ibd
rw-rr- 1 Andrii 197609 98304 Dec 7 11:43 fts_0000000000000014_000000000000001e_index_4.ibd
rw-rr- 1 Andrii 197609 98304 Dec 7 11:43 fts_0000000000000014_000000000000001e_index_5.ibd
rw-rr- 1 Andrii 197609 0 Dec 7 11:43 fts_0000000000000014_000000000000001e_index_6.ibd

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

It looks file was copied while it was modified by mysqld :
File modification timestamp in datadir 11:43:40.822
File modification timestamp in backup : 11:43:40.528

Comment by Vladislav Vaintroub [ 2016-12-07 ]

I think this can be split into different bugs, now that we know getByteOrder@SHA512 does not crash. There is something with empty files. And there is something else as well.

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

Sorry for confusion - I think getByteOrder@SHA512 is just incorrect symbols because I somehow built without debug info. We should change ticket description to something more relevant to crash discussed.
I am sure that this whole problem is related to concurrency during .ibd file creation. Not sure why it is reproducible only with encryption and FULLTEXT - maybe they just increase probability of crash.

Comment by Vladislav Vaintroub [ 2016-12-07 ]

I pushed a tentative fix for small ibd , including a test
https://github.com/MariaDB/server/blob/bb-10.1-wlad-xtrabackup/mysql-test/suite/xtrabackup/small_ibd.test

It is hard to reproduce on my machine with full text and encryption.
But it is true, that races like that can legitimately happen, without fulltext and without encryption, as the server is allowed to run, and CREATE TABLE while xtrabackup is running in parallel. Half created files should be excluded, we should rely on recovery to rerun the redo logs, and recreate files, if they are not there yet.

I'm not 100% sure whether fulltext example you have given pinpoints to some bug in xtradb/encryption/fulltext combination - I personally did not expect that there is a lot of files created after CREATE TABLE has successfully finished- we are not running anything in parallel in your example. Yet I'm not intimately familiar with the subject, and think this is outside of xtrabackup scope. Maybe it makes sense to consult Jan on this.

Comment by Andrii Nikitin (Inactive) [ 2016-12-08 ]

Still crashing.
This report has too much irrelevant info from the start, closing it and opening MDEV-11502 to track the problem further.

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