[MDEV-18183] Server startup fails while dropping garbage encrypted tablespace - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.4(EOL)
Fix Version/s: 10.4.2, 10.1.38, 10.2.22, 10.3.13
Component/s: mariabackup, Storage Engine - InnoDB
Labels:
None

Description

10.4 30da40bb8
mysqld: /data/src/10.4/storage/innobase/include/sync0policy.h:62: MutexDebug<Mutex>::Context::Context(latch_id_t) [with Mutex = TTASEventMutex<GenericPolicy>]: Assertion `id != LATCH_ID_NONE' failed.
190109 14:21:52 [ERROR] mysqld got signal 6 ;

#7 0x00007f4a57fb6ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x000055e6d4a192e9 in MutexDebug<TTASEventMutex<GenericPolicy> >::Context::Context (this=0x7ffce2e1e520, id=LATCH_ID_NONE) at /data/src/10.4/storage/innobase/include/sync0policy.h:62
#9 0x000055e6d4a17b0a in MutexDebug<TTASEventMutex<GenericPolicy> >::enter (this=0x55e6d643a1d0 <fil_crypt_threads_mutex+16>, mutex=0x55e6d643a1c0 <fil_crypt_threads_mutex>, name=0x55e6d52a7ec0 "/data/src/10.4/storage/innobase/fil/fil0crypt.cc", line=2370) at /data/src/10.4/storage/innobase/include/sync0policy.ic:66
#10 0x000055e6d4a168fa in GenericPolicy<TTASEventMutex<GenericPolicy> >::enter (this=0x55e6d643a1d0 <fil_crypt_threads_mutex+16>, mutex=..., filename=0x55e6d52a7ec0 "/data/src/10.4/storage/innobase/fil/fil0crypt.cc", line=2370) at /data/src/10.4/storage/innobase/include/sync0policy.h:345
#11 0x000055e6d4a14cf7 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55e6d643a1c0 <fil_crypt_threads_mutex>, n_spins=30, n_delay=4, name=0x55e6d52a7ec0 "/data/src/10.4/storage/innobase/fil/fil0crypt.cc", line=2370) at /data/src/10.4/storage/innobase/include/ib0mutex.h:594
#12 0x000055e6d4d28e32 in fil_space_crypt_close_tablespace (space=0x55e6d8a1c340) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2370
#13 0x000055e6d4d17df4 in fil_check_pending_operations (id=639, operation=FIL_OPERATION_DELETE, space=0x7ffce2e1e860, path=0x7ffce2e1e858) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:2392
#14 0x000055e6d4d18377 in fil_delete_tablespace (id=639, drop_ahi=false) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:2551
#15 0x000055e6d4b601b4 in row_drop_table_for_mysql (name=0x55e6d8a1e9a8 "test/#sql-1910_e#P#ver_p1", trx=0x7f4a549b7118, sqlcom=SQLCOM_DROP_TABLE, create_failed=false, nonatomic=true) at /data/src/10.4/storage/innobase/row/row0mysql.cc:3768
#16 0x000055e6d4b5dc25 in row_mysql_drop_garbage_tables () at /data/src/10.4/storage/innobase/row/row0mysql.cc:2771
#17 0x000055e6d4aaf788 in recv_recovery_rollback_active () at /data/src/10.4/storage/innobase/log/log0recv.cc:3563
#18 0x000055e6d4bc5c54 in srv_start (create_new_db=false) at /data/src/10.4/storage/innobase/srv/srv0start.cc:2145
#19 0x000055e6d49edf5f in innodb_init (p=0x55e6d7e99550) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:4252
#20 0x000055e6d46c1f8d in ha_initialize_handlerton (plugin=0x55e6d7dcb608) at /data/src/10.4/sql/handler.cc:523
#21 0x000055e6d43c8deb in plugin_initialize (tmp_root=0x7ffce2e26360, plugin=0x55e6d7dcb608, argc=0x55e6d5baaf30 <remaining_argc>, argv=0x55e6d7d753d8, options_only=false) at /data/src/10.4/sql/sql_plugin.cc:1437
#22 0x000055e6d43c9a80 in plugin_init (argc=0x55e6d5baaf30 <remaining_argc>, argv=0x55e6d7d753d8, flags=0) at /data/src/10.4/sql/sql_plugin.cc:1720
#23 0x000055e6d4287959 in init_server_components () at /data/src/10.4/sql/mysqld.cc:5333
#24 0x000055e6d4288abe in mysqld_main (argc=19, argv=0x55e6d7d753d8) at /data/src/10.4/sql/mysqld.cc:5860
#25 0x000055e6d427cf20 in main (argc=19, argv=0x7ffce2e26b98) at /data/src/10.4/sql/main.cc:25

The backup dir (stored after prepare but before any server startup was attempted) is attached. To reproduce the failure, restore it to the datadir and start the server with

--innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --file-key-management --plugin-load-add=file_key_management --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt

(modify file-key-management-filename value as needed).

Notes on the origin of the report. Please be aware it's not easily reproducible the same way, the test is concurrent by nature, and apparently there is a race condition involved.

The problem initially happened by running the concurrent test with MariaBackupFull scenario:

github.com/MariaDB/randgen elenst-dev 5342873c97, github.com/elenst/mariadb-toolbox master 6ded4b71568

perl ./runall-new.pl --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir --duration=350 --threads=4 --seed=1547032787 --reporters=Backtrace,ErrorLog,Deadlock --skip-gendata --gendata-advanced --views --grammar=conf/mariadb/generic-dml.yy --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --filter=/home/travis/mariadb-toolbox/travis/10.4-combo-filter.ff --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4 --mysqld=--aria-encrypt-tables=1 --mysqld=--encrypt-tmp-disk-tables=1 --mysqld=--file-key-management --mysqld=--file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --mysqld=--plugin-load-add=file_key_management --engine=Aria --scenario=MariaBackupFull --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/sequences.yy

The test performs the following steps:

start the server with

/home/travis/server/bin/mysqld --no-defaults --basedir=/home/travis/server --lc-messages-dir=/home/travis/server/share --character-sets-dir=/home/travis/server/share/charsets --tmpdir=/home/travis/logs/vardir/tmp --core-file --datadir=/home/travis/logs/vardir/data --max-allowed-packet=128Mb --port=19300 --socket=/home/travis/logs/vardir/mysql.sock --pid-file=/home/travis/logs/vardir/mysql.pid --general-log --general-log-file=/home/travis/logs/vardir/mysql.log --log_output=FILE --max-statement-time=20 --lock-wait-timeout=10 --loose-innodb-lock-wait-timeout=5 --loose-debug_assert_on_not_freed_memory=0 --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --file-key-management --file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --plugin-load-add=file_key_management

run concurrent DML/DDL flow on the server;
after ~100 seconds, take the full backup from the running server (succeeded, the log attached as mbackup_backup.log;
after another ~100 seconds, shut down the server gracefully (succeeded, the error log is attached as mysql.err_orig;
run mariabackup --prepare (succeded, the log attached as mbackup_prepare.log;
cleanup server datadir and restore the backup to it (succeeded, the log attached as mbackup_restore.log;
try to start the server with the same options as before.

I have no information yet whether the problem happens on earlier versions.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

backup.tar.gz
2019-01-09 12:38
4.85 MB
Elena Stepanova
mbackup_backup.log
2019-01-09 12:48
57 kB
Elena Stepanova
mbackup_prepare.log
2019-01-09 12:50
12 kB
Elena Stepanova
mbackup_restore.log
2019-01-09 12:52
17 kB
Elena Stepanova
mdev-18183-10.2v1.patch
2019-01-16 17:34
3 kB
Thirunarayanan Balathandayuthapani
mysql.err_orig
2019-01-09 12:50
191 kB
Elena Stepanova

Issue Links

relates to

MDEV-18279 MLOG_FILE_WRITE_CRYPT_DATA fails to set the crypt_data->type for tablespace.

Closed

MDEV-19914 Server startup fails while dropping garbage encrypted tablespace if innodb_encryption_threads > 0

Closed

Server startup fails while dropping garbage encrypted tablespace

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration