Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-18183

Server startup fails while dropping garbage encrypted tablespace

    XMLWordPrintable

    Details

      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

        1. backup.tar.gz
          4.85 MB
        2. mbackup_backup.log
          57 kB
        3. mbackup_prepare.log
          12 kB
        4. mbackup_restore.log
          17 kB
        5. mdev-18183-10.2v1.patch
          3 kB
        6. mysql.err_orig
          191 kB

          Issue Links

            Activity

              People

              Assignee:
              thiru Thirunarayanan Balathandayuthapani
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: