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

InnoDB may crash when required compression plugins are not loaded

Details

    Description

      The tests plugins.compression and mariabackup.compression_providers_unloaded crash very often on the ASAN builder. AddressSanitizer probably only matters for the timing characteristics.

      Here is a 10.7 run where both tests crash:

      10.7 9055db2f28b9e6b2c16810fb78d4cc23f86d005e

      mariabackup.compression_providers_unloaded 'lzo' w6 [ fail ]
              Test ended at 2022-02-09 03:15:18
       
      CURRENT_TEST: mariabackup.compression_providers_unloaded
      2022-02-09  3:15:15 0 [ERROR] InnoDB: Failed to read page 2 from file './test/t1.ibd': Table is compressed or encrypted but uncompress or decrypt failed.
      mariadbd: /home/buildbot/buildbot/build/mariadb-10.7.3/storage/innobase/buf/buf0buf.cc:2897: buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, mtr_t*, dberr_t*, bool): Assertion `block->page.id() == page_id' failed.
      buf/buf0buf.cc:2902(buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x55d0fa79416a]
      buf/buf0buf.cc:2993(buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x55d0fa8529e0]
      dict/dict0load.cc:2367(dict_load_table_one(st_::span<char const> const&, dict_err_ignore_t, std::deque<char const*, ut_allocator<char const*, true> >&))[0x55d0fa85399a]
      dict/dict0load.cc:2461(dict_sys_t::load_table(st_::span<char const> const&, dict_err_ignore_t))[0x55d0fa854298]
      dict/dict0load.cc:2549(dict_load_table_on_id(unsigned long, dict_err_ignore_t))[0x55d0fa818123]
      dict/dict0dict.cc:851(dict_table_open_on_id(unsigned long, bool, dict_table_op_t, THD*, MDL_ticket**))[0x55d0fa594d34]
      row/row0purge.cc:1028(row_purge_parse_undo_rec(purge_node_t*, unsigned char*, que_thr_t*, bool*))[0x55d0fa5965e6]
      

      and

      10.7 9055db2f28b9e6b2c16810fb78d4cc23f86d005e

      plugins.compression 'innodb-lzo'         w4 [ fail ]
              Test ended at 2022-02-09 03:15:51
       
      CURRENT_TEST: plugins.compression
      mysqltest: At line 43: query 'select a, left(b, 9), length(b) from t1' failed with wrong errno <Unknown> (2013): 'Lost connection to server during query', instead of ER_PROVIDER_NOT_LOADED (4185)...
      buf/buf0buf.cc:2902(buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x56031b5f316a]
      buf/buf0buf.cc:2993(buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x56031b6b19e0]
      dict/dict0load.cc:2367(dict_load_table_one(st_::span<char const> const&, dict_err_ignore_t, std::deque<char const*, ut_allocator<char const*, true> >&))[0x56031b6b299a]
      dict/dict0load.cc:2461(dict_sys_t::load_table(st_::span<char const> const&, dict_err_ignore_t))[0x56031b6b3298]
      dict/dict0load.cc:2549(dict_load_table_on_id(unsigned long, dict_err_ignore_t))[0x56031b677123]
      dict/dict0dict.cc:851(dict_table_open_on_id(unsigned long, bool, dict_table_op_t, THD*, MDL_ticket**))[0x56031b3f3d34]
      row/row0purge.cc:1028(row_purge_parse_undo_rec(purge_node_t*, unsigned char*, que_thr_t*, bool*))[0x56031b3f55e6]
      

      In the latter crash, the table is being opened for the purge of history of committed transactions.

      It is not sufficient to block access to the table at the SQL layer. InnoDB may open tables internally, either for purging history, or for rolling back changes to recovered transactions.

      If you want to prevent such crashes, then the server should be started with innodb_force_recovery=3. There has been no requirement to ensure that everything has been rolled back and purged before upgrading the server. We only require a clean shutdown from an earlier version, when upgrading to 10.2, 10.3, 10.5, 10.8. For the upgrade to 10.3 it is due to an undo log format change (MDEV-12288); an upgrade sanity check was implemented in MDEV-15912. For other versions, it is due to a redo log format change (MDEV-12353 in 10.5 and MDEV-14425 in 10.8).

      I encountered also failures like this:

      plugins.compression 'innodb-snappy'      w5 [ fail ]
              Test ended at 2022-02-17 15:33:40
       
      CURRENT_TEST: plugins.compression
      mysqltest: At line 43: query 'select a, left(b, 9), length(b) from t1' succeeded - should have failed with error ER_PROVIDER_NOT_LOADED (4185)...
      

      Attachments

        Issue Links

          Activity

            mleich Matthias Leich added a comment - - edited

            The assert described on top was also observed two times during RQG testing.
             
            mleich@pluto:/RQG_N$ grep TBR-1353 /data/results/*/result.* | grep -v '],'
            /data/results/1642758604/result.new:STATUS_BACKUP_FAILURE--TBR-1353        /data/results/1642758604/002555.log    /data/results/1642758604/002555.tar.xz 162652KB
            /data/results/1642758604/result.new:STATUS_BACKUP_FAILURE--TBR-1353--TBR-1134        /data/results/1642758604/002224.log    /data/results/1642758604/002224.tar.xz 
            150384KB
            Fragment of RQG calls
            --grammar=conf/mariadb/innodb_compression_encryption.yy --gendata=conf/mariadb/innodb_compression_encryption.zz --max_gd_duration=1800 --mysqld=--innodb-encrypt-log --mysqld=--innodb-encrypt-tables --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs --mysqld=--loose-idle_write_transaction_timeout=0 --mysqld=--loose-idle_transaction_timeout=0 --mysqld=--loose-idle_readonly_transaction_timeout=0 --mysqld=--connect_timeout=60 --mysqld=--interactive_timeout=28800 --mysqld=--slave_net_timeout=60 --mysqld=--net_read_timeout=30 --mysqld=--net_write_timeout=60 --mysqld=--loose-table_lock_wait_timeout=50 --mysqld=--wait_timeout=28800 --mysqld=--lock-wait-timeout=86400 --mysqld=--innodb-lock-wait-timeout=50 --no-mask --queries=10000000 --seed=random --reporters=Backtrace --reporters=ErrorLog --reporters=Deadlock1 --validators=None --mysqld=--log_output=none --mysqld=--log_bin_trust_function_creators=1 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=InnoDB --restart_timeout=360 --mysqld=--plugin-load-add=file_key_management.so --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt --mysqld=--plugin-load-add=provider_lzo.so --mysqld=--plugin-load-add=provider_bzip2.so --mysqld=--plugin-load-add=provider_lzma --mysqld=--plugin-load-add=provider_snappy --mysqld=--plugin-load-add=provider_lz4 --duration=300 --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 --mysqld=--loose-innodb_read_only_compressed=OFF --reporters=Mariabackup_linux --mysqld=--innodb_log_file_size=402653184 --duration=300 --mysqld=--innodb_stats_persistent=off --mysqld=--innodb_adaptive_hash_index=on --mysqld=--loose-innodb_evict_tables_on_commit_debug=off --mysqld=--loose-max-statement-time=30 --threads=2 --mysqld=--innodb_use_native_aio=1 --mysqld=--innodb_rollback_on_timeout=OFF --vardir_type=fast --mysqld=--innodb_page_size=16K --mysqld=--innodb-buffer-pool-size=8M --no_mask
            --grammar=conf/mariadb/innodb_compression_encryption.yy --gendata=conf/mariadb/innodb_compression_encryption.zz --max_gd_duration=1800 --mysqld=--innodb-encrypt-log --mysqld=--innodb-encrypt-tables --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs --mysqld=--loose-idle_write_transaction_timeout=0 --mysqld=--loose-idle_transaction_timeout=0 --mysqld=--loose-idle_readonly_transaction_timeout=0 --mysqld=--connect_timeout=60 --mysqld=--interactive_timeout=28800 --mysqld=--slave_net_timeout=60 --mysqld=--net_read_timeout=30 --mysqld=--net_write_timeout=60 --mysqld=--loose-table_lock_wait_timeout=50 --mysqld=--wait_timeout=28800 --mysqld=--lock-wait-timeout=86400 --mysqld=--innodb-lock-wait-timeout=50 --no-mask --queries=10000000 --seed=random --reporters=Backtrace --reporters=ErrorLog --reporters=Deadlock1 --validators=None --mysqld=--log_output=none --mysqld=--log_bin_trust_function_creators=1 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=InnoDB --restart_timeout=360 --mysqld=--plugin-load-add=file_key_management.so --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt --mysqld=--plugin-load-add=provider_lzo.so --mysqld=--plugin-load-add=provider_bzip2.so --mysqld=--plugin-load-add=provider_lzma --mysqld=--plugin-load-add=provider_snappy --mysqld=--plugin-load-add=provider_lz4 --duration=300 --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 --mysqld=--loose-innodb_read_only_compressed=OFF --reporters=Mariabackup_linux --mysqld=--innodb_log_file_size=402653184 --duration=300 --mysqld=--innodb_stats_persistent=off --mysqld=--innodb_adaptive_hash_index=off --mysqld=--loose-innodb_evict_tables_on_commit_debug=off --mysqld=--loose-max-statement-time=30 --threads=2 --mysqld=--innodb_use_native_aio=1 --mysqld=--innodb_rollback_on_timeout=OFF --vardir_type=fast --mysqld=--innodb_page_size=16K --mysqld=--innodb-buffer-pool-size=8M --no_mask
             
            Error pattern for RQG
            [ 'TBR-1353', 'ERROR: Reporter Mariabackup : Starting a DB server on the cloned data failed.+ Executing backup: .+ Executing first prepare: .+ INFO: Attempt to start a DB server on the cloned data..+mysqld: .{1,250}buf0buf.cc:.{1,6}: buf_block_t\* buf_page_get_low.{1,150}: Assertion \`block->page.id\(\) == page_id\' failed.+RESULT: The RQG run ended with status STATUS_BACKUP_FAILURE' ],
             
            origin/10.8 baef53a70c675da6d19ac3c7f23c7b8b4ed8458c 2022-01-20T16:01:10+01:00
             
            Scenario:
               The source server is under concurrent DDL and DML load caused b two sessions.
               In parallel to that runs
               1. mariabackup --backup to location A,
               2. mariabackup --prepare on location A
               3. attempt to start a DB server on location A
                   The system options are like the one of the source server except, data dir, ports etc.
            2022-01-21 11:36:17 0 [Note] /data/Server_bin/10.8_asan/bin/mysqld (server 10.8.0-MariaDB-debug-log) starting as process 1305475 ...
            2022-01-21 11:36:17 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
            2022-01-21 11:36:17 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
            2022-01-21 11:36:17 0 [Note] InnoDB: Number of transaction pools: 1
            2022-01-21 11:36:17 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
            2022-01-21 11:36:17 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
            2022-01-21 11:36:17 0 [Note] InnoDB: Completed initialization of buffer pool
            2022-01-21 11:36:17 0 [Note] InnoDB: Setting O_DIRECT on file ./ibdata1 failed
            2022-01-21 11:36:17 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 96.000MiB
            2022-01-21 11:36:18 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
            2022-01-21 11:36:18 0 [Note] InnoDB: New log file created, LSN=45103784
            2022-01-21 11:36:18 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
            2022-01-21 11:36:18 0 [Note] InnoDB: Trx id counter is 72
            2022-01-21 11:36:18 0 [Note] InnoDB: 128 rollback segments are active.
            2022-01-21 11:36:18 0 [Note] InnoDB: Creating shared tablespace for temporary tables
            2022-01-21 11:36:18 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
            2022-01-21 11:36:18 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
            2022-01-21 11:36:18 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
            2022-01-21 11:36:18 0 [ERROR] InnoDB: Encrypted page [page id: space=8, page number=18] in file ./test/t4.ibd looks corrupted; key_version=1
            mysqld: /data/Server/10.8/storage/innobase/buf/buf0buf.cc:2901: buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, mtr_t*, dberr_t*, bool): Assertion `block->page.id() == page_id' failed.
            220121 11:36:18 [ERROR] mysqld got signal 6 ;
            ...
            ??:0(__assert_fail)[0x7fe3da9fdf36]
            /data/Server_bin/10.8_asan/bin/mysqld(+0x2dfd9a9)[0x5558d17779a9]
            /data/Server_bin/10.8_asan/bin/mysqld(+0x2dfe3cb)[0x5558d17783cb]
            buf/buf0buf.cc:2906(buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x5558d1280279]
            /data/Server_bin/10.8_asan/bin/mysqld(+0x2d8ff66)[0x5558d1709f66]
            include/btr0btr.h:212(btr_block_get(dict_index_t const&, unsigned int, unsigned long, bool, mtr_t*))[0x5558d17144a7]
            btr/btr0cur.cc:275(btr_cur_latch_leaves(buf_block_t*, unsigned long, btr_cur_t*, mtr_t*))[0x5558d1744790]
            include/btr0pcur.ic:427(btr_pcur_open_with_no_init_func(dict_index_t*, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, ssux_lock_impl<true>*, mtr_t*))[0x5558d17477d9]
            row/row0uins.cc:238(row_undo_ins_remove_clust_rec(undo_node_t*))[0x5558d198e7bf]
            row/row0uins.cc:649(row_undo_ins(undo_node_t*, que_thr_t*))[0x5558d1991244]
            row/row0undo.cc:409(row_undo(undo_node_t*, que_thr_t*))[0x5558d15d3dc5]
            row/row0undo.cc:460(row_undo_step(que_thr_t*))[0x5558d15d42ba]
            que/que0que.cc:651(que_thr_step(que_thr_t*))[0x5558d1476e71]
            que/que0que.cc:709(que_run_threads_low(que_thr_t*))[0x5558d1477235]
            que/que0que.cc:731(que_run_threads(que_thr_t*))[0x5558d14773d7]
            trx/trx0roll.cc:605(trx_rollback_active(trx_t*))[0x5558d166e633]
            trx/trx0roll.cc:741(trx_rollback_recovered(bool))[0x5558d166f7e7]
            trx/trx0roll.cc:787(trx_rollback_all_recovered(void*))[0x5558d166fe97]
            tpool/task_group.cc:56(tpool::task_group::execute(tpool::task*))[0x5558d19cda94]
            tpool/task.cc:40(tpool::task::execute())[0x5558d19ce35d]
            tpool/tpool_generic.cc:547(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x5558d19bab0b]
            bits/invoke.h:73(void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5558d19cd4f5]
            bits/invoke.h:96(std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5558d19cd2a0]
            9/thread:244(void std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul>(std::_Index_tuple<0ul, 1ul, 2ul>))[0x5558d19cd131]
            9/thread:247(std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()())[0x5558d19cd07b]
            9/thread:195(std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run())[0x5558d19ccfe0]
            ??:0(std::error_code::default_error_condition() const)[0x7fe3dadfbde4]
            nptl/pthread_create.c:478(start_thread)[0x7fe3daf16609]
            ??:0(clone)[0x7fe3daae9293]
            
            

            mleich Matthias Leich added a comment - - edited The assert described on top was also observed two times during RQG testing.   mleich@pluto:/RQG_N$ grep TBR-1353 /data/results/*/result.* | grep -v '],' /data/results/1642758604/result.new:STATUS_BACKUP_FAILURE--TBR-1353 /data/results/1642758604/002555.log /data/results/1642758604/002555.tar.xz 162652KB /data/results/1642758604/result.new:STATUS_BACKUP_FAILURE--TBR-1353--TBR-1134 /data/results/1642758604/002224.log /data/results/1642758604/002224.tar.xz 150384KB Fragment of RQG calls --grammar=conf/mariadb/innodb_compression_encryption.yy --gendata=conf/mariadb/innodb_compression_encryption.zz --max_gd_duration=1800 --mysqld=--innodb-encrypt-log --mysqld=--innodb-encrypt-tables --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs --mysqld=--loose-idle_write_transaction_timeout=0 --mysqld=--loose-idle_transaction_timeout=0 --mysqld=--loose-idle_readonly_transaction_timeout=0 --mysqld=--connect_timeout=60 --mysqld=--interactive_timeout=28800 --mysqld=--slave_net_timeout=60 --mysqld=--net_read_timeout=30 --mysqld=--net_write_timeout=60 --mysqld=--loose-table_lock_wait_timeout=50 --mysqld=--wait_timeout=28800 --mysqld=--lock-wait-timeout=86400 --mysqld=--innodb-lock-wait-timeout=50 --no-mask --queries=10000000 --seed=random --reporters=Backtrace --reporters=ErrorLog --reporters=Deadlock1 --validators=None --mysqld=--log_output=none --mysqld=--log_bin_trust_function_creators=1 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=InnoDB --restart_timeout=360 --mysqld=--plugin-load-add=file_key_management.so --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt --mysqld=--plugin-load-add=provider_lzo.so --mysqld=--plugin-load-add=provider_bzip2.so --mysqld=--plugin-load-add=provider_lzma --mysqld=--plugin-load-add=provider_snappy --mysqld=--plugin-load-add=provider_lz4 --duration=300 --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 --mysqld=--loose-innodb_read_only_compressed=OFF --reporters=Mariabackup_linux --mysqld=--innodb_log_file_size=402653184 --duration=300 --mysqld=--innodb_stats_persistent=off --mysqld=--innodb_adaptive_hash_index=on --mysqld=--loose-innodb_evict_tables_on_commit_debug=off --mysqld=--loose-max-statement-time=30 --threads=2 --mysqld=--innodb_use_native_aio=1 --mysqld=--innodb_rollback_on_timeout=OFF --vardir_type=fast --mysqld=--innodb_page_size=16K --mysqld=--innodb-buffer-pool-size=8M --no_mask --grammar=conf/mariadb/innodb_compression_encryption.yy --gendata=conf/mariadb/innodb_compression_encryption.zz --max_gd_duration=1800 --mysqld=--innodb-encrypt-log --mysqld=--innodb-encrypt-tables --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs --mysqld=--loose-idle_write_transaction_timeout=0 --mysqld=--loose-idle_transaction_timeout=0 --mysqld=--loose-idle_readonly_transaction_timeout=0 --mysqld=--connect_timeout=60 --mysqld=--interactive_timeout=28800 --mysqld=--slave_net_timeout=60 --mysqld=--net_read_timeout=30 --mysqld=--net_write_timeout=60 --mysqld=--loose-table_lock_wait_timeout=50 --mysqld=--wait_timeout=28800 --mysqld=--lock-wait-timeout=86400 --mysqld=--innodb-lock-wait-timeout=50 --no-mask --queries=10000000 --seed=random --reporters=Backtrace --reporters=ErrorLog --reporters=Deadlock1 --validators=None --mysqld=--log_output=none --mysqld=--log_bin_trust_function_creators=1 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --engine=InnoDB --restart_timeout=360 --mysqld=--plugin-load-add=file_key_management.so --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt --mysqld=--plugin-load-add=provider_lzo.so --mysqld=--plugin-load-add=provider_bzip2.so --mysqld=--plugin-load-add=provider_lzma --mysqld=--plugin-load-add=provider_snappy --mysqld=--plugin-load-add=provider_lz4 --duration=300 --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 --mysqld=--loose-innodb_read_only_compressed=OFF --reporters=Mariabackup_linux --mysqld=--innodb_log_file_size=402653184 --duration=300 --mysqld=--innodb_stats_persistent=off --mysqld=--innodb_adaptive_hash_index=off --mysqld=--loose-innodb_evict_tables_on_commit_debug=off --mysqld=--loose-max-statement-time=30 --threads=2 --mysqld=--innodb_use_native_aio=1 --mysqld=--innodb_rollback_on_timeout=OFF --vardir_type=fast --mysqld=--innodb_page_size=16K --mysqld=--innodb-buffer-pool-size=8M --no_mask   Error pattern for RQG [ 'TBR-1353', 'ERROR: Reporter Mariabackup : Starting a DB server on the cloned data failed.+ Executing backup: .+ Executing first prepare: .+ INFO: Attempt to start a DB server on the cloned data..+mysqld: .{1,250}buf0buf.cc:.{1,6}: buf_block_t\* buf_page_get_low.{1,150}: Assertion \`block->page.id\(\) == page_id\' failed.+RESULT: The RQG run ended with status STATUS_BACKUP_FAILURE' ],   origin/10.8 baef53a70c675da6d19ac3c7f23c7b8b4ed8458c 2022-01-20T16:01:10+01:00   Scenario: The source server is under concurrent DDL and DML load caused b two sessions. In parallel to that runs 1. mariabackup --backup to location A, 2. mariabackup --prepare on location A 3. attempt to start a DB server on location A The system options are like the one of the source server except, data dir, ports etc. 2022-01-21 11:36:17 0 [Note] /data/Server_bin/10.8_asan/bin/mysqld (server 10.8.0-MariaDB-debug-log) starting as process 1305475 ... 2022-01-21 11:36:17 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!! 2022-01-21 11:36:17 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2022-01-21 11:36:17 0 [Note] InnoDB: Number of transaction pools: 1 2022-01-21 11:36:17 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2022-01-21 11:36:17 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB 2022-01-21 11:36:17 0 [Note] InnoDB: Completed initialization of buffer pool 2022-01-21 11:36:17 0 [Note] InnoDB: Setting O_DIRECT on file ./ibdata1 failed 2022-01-21 11:36:17 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 96.000MiB 2022-01-21 11:36:18 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0 2022-01-21 11:36:18 0 [Note] InnoDB: New log file created, LSN=45103784 2022-01-21 11:36:18 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo 2022-01-21 11:36:18 0 [Note] InnoDB: Trx id counter is 72 2022-01-21 11:36:18 0 [Note] InnoDB: 128 rollback segments are active. 2022-01-21 11:36:18 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2022-01-21 11:36:18 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ... 2022-01-21 11:36:18 0 [Note] InnoDB: Starting in background the rollback of recovered transactions 2022-01-21 11:36:18 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB. 2022-01-21 11:36:18 0 [ERROR] InnoDB: Encrypted page [page id: space=8, page number=18] in file ./test/t4.ibd looks corrupted; key_version=1 mysqld: /data/Server/10.8/storage/innobase/buf/buf0buf.cc:2901: buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, mtr_t*, dberr_t*, bool): Assertion `block->page.id() == page_id' failed. 220121 11:36:18 [ERROR] mysqld got signal 6 ; ... ??:0(__assert_fail)[0x7fe3da9fdf36] /data/Server_bin/10.8_asan/bin/mysqld(+0x2dfd9a9)[0x5558d17779a9] /data/Server_bin/10.8_asan/bin/mysqld(+0x2dfe3cb)[0x5558d17783cb] buf/buf0buf.cc:2906(buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x5558d1280279] /data/Server_bin/10.8_asan/bin/mysqld(+0x2d8ff66)[0x5558d1709f66] include/btr0btr.h:212(btr_block_get(dict_index_t const&, unsigned int, unsigned long, bool, mtr_t*))[0x5558d17144a7] btr/btr0cur.cc:275(btr_cur_latch_leaves(buf_block_t*, unsigned long, btr_cur_t*, mtr_t*))[0x5558d1744790] include/btr0pcur.ic:427(btr_pcur_open_with_no_init_func(dict_index_t*, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, ssux_lock_impl<true>*, mtr_t*))[0x5558d17477d9] row/row0uins.cc:238(row_undo_ins_remove_clust_rec(undo_node_t*))[0x5558d198e7bf] row/row0uins.cc:649(row_undo_ins(undo_node_t*, que_thr_t*))[0x5558d1991244] row/row0undo.cc:409(row_undo(undo_node_t*, que_thr_t*))[0x5558d15d3dc5] row/row0undo.cc:460(row_undo_step(que_thr_t*))[0x5558d15d42ba] que/que0que.cc:651(que_thr_step(que_thr_t*))[0x5558d1476e71] que/que0que.cc:709(que_run_threads_low(que_thr_t*))[0x5558d1477235] que/que0que.cc:731(que_run_threads(que_thr_t*))[0x5558d14773d7] trx/trx0roll.cc:605(trx_rollback_active(trx_t*))[0x5558d166e633] trx/trx0roll.cc:741(trx_rollback_recovered(bool))[0x5558d166f7e7] trx/trx0roll.cc:787(trx_rollback_all_recovered(void*))[0x5558d166fe97] tpool/task_group.cc:56(tpool::task_group::execute(tpool::task*))[0x5558d19cda94] tpool/task.cc:40(tpool::task::execute())[0x5558d19ce35d] tpool/tpool_generic.cc:547(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x5558d19bab0b] bits/invoke.h:73(void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5558d19cd4f5] bits/invoke.h:96(std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5558d19cd2a0] 9/thread:244(void std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul>(std::_Index_tuple<0ul, 1ul, 2ul>))[0x5558d19cd131] 9/thread:247(std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()())[0x5558d19cd07b] 9/thread:195(std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run())[0x5558d19ccfe0] ??:0(std::error_code::default_error_condition() const)[0x7fe3dadfbde4] nptl/pthread_create.c:478(start_thread)[0x7fe3daf16609] ??:0(clone)[0x7fe3daae9293]

            mleich, thank you. After mariadb-backup --prepare, all redo log would have been applied, but there may exist incomplete transactions in the undo log pages. The stack trace is from the rollback of such an incomplete recovered transaction.

            marko Marko Mäkelä added a comment - mleich , thank you. After mariadb-backup --prepare , all redo log would have been applied, but there may exist incomplete transactions in the undo log pages. The stack trace is from the rollback of such an incomplete recovered transaction.

            I couldn't repeat either crash in ASAN builds. Any ideas how I can repeat them?

            serg Sergei Golubchik added a comment - I couldn't repeat either crash in ASAN builds. Any ideas how I can repeat them?

            Attempts to replay the problem based on the MTR tests mentioned above. No success

            mleich Matthias Leich added a comment - Attempts to replay the problem based on the MTR tests mentioned above. No success
            marko Marko Mäkelä added a comment - - edited

            serg, I reopened the earlier report MDEV-27339 and provided there a repeatable test case that causes a form of corruption in InnoDB.

            When it comes to the test mariabackup.compression_providers_unloaded, according to the cross-reference it is missing some suppression. Even if you ignore the failures on IBM AIX, it seems to fail almost every day somewhere.

            For plugins.compression, here is yet another type of failure:

            10.9 c132bce1a18480b3d545a056b8573b2f

            CURRENT_TEST: plugins.compression
            mysqltest: At line 43: query 'select a, left(b, 9), length(b) from t1' failed with wrong errno ER_NO_SUCH_TABLE_IN_ENGINE (1932): 'Table 'test.t1' doesn't exist in engine', instead of ER_PROVIDER_NOT_LOADED (4185)...
            

            marko Marko Mäkelä added a comment - - edited serg , I reopened the earlier report MDEV-27339 and provided there a repeatable test case that causes a form of corruption in InnoDB. When it comes to the test mariabackup.compression_providers_unloaded , according to the cross-reference it is missing some suppression. Even if you ignore the failures on IBM AIX, it seems to fail almost every day somewhere. For plugins.compression , here is yet another type of failure : 10.9 c132bce1a18480b3d545a056b8573b2f CURRENT_TEST: plugins.compression mysqltest: At line 43: query 'select a, left(b, 9), length(b) from t1' failed with wrong errno ER_NO_SUCH_TABLE_IN_ENGINE (1932): 'Table 'test.t1' doesn't exist in engine', instead of ER_PROVIDER_NOT_LOADED (4185)...

            There are some signs of memory corruption as well, in one particular environment:
            https://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-aarch64/builds/14264

            10.7 bdd80e3fb1cb653c367099639bec46840eca86e1

            plugins.compression 'innodb-lzo'         w1 [ fail ]  Found warnings/errors in server log file!
                    Test ended at 2022-08-24 09:52:15
            line
            220824  9:51:12 [ERROR] mysqld got signal 11 ;
            Attempting backtrace. You can use the following information to find out
            ^ Found warnings in /dev/shm/var/1/log/mysqld.1.err
            ok
             
             - found 'core.22329' (0/0)
            #16 0x0000aaaab6d79e58 in handle_fatal_signal (sig=11) at /usr/src/debug/MariaDB-/src_0/sql/signal_handler.cc:234
            #17 <signal handler called>
            #18 0x0000ffff796aa8b8 in _int_free () from /lib64/libc.so.6
            #19 0x0000aaaab71b8bc4 in aligned_free (ptr=0xaaaac1e8c000) at /usr/src/debug/MariaDB-/src_0/include/aligned.h:37
            #20 0x0000aaaab71ba33c in buf_pool_t::io_buf_t::close (this=0xaaaab7bba848 <buf_pool+37832>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/include/buf0buf.h:1901
            #21 0x0000aaaab71b3fe8 in buf_pool_t::close (this=0xaaaab7bb1480 <buf_pool>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0buf.cc:1167
            #22 0x0000aaaab7137364 in innodb_shutdown () at /usr/src/debug/MariaDB-/src_0/storage/innobase/srv/srv0start.cc:2055
            #23 0x0000aaaab701ff30 in innobase_end () at /usr/src/debug/MariaDB-/src_0/storage/innobase/handler/ha_innodb.cc:4377
            #24 0x0000aaaab6d7c5b0 in ha_finalize_handlerton (plugin=0xaaaac15634e0) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:596
            #25 0x0000aaaab6b90308 in plugin_deinitialize (plugin=0xaaaac15634e0, ref_check=ref_check@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1272
            #26 0x0000aaaab6b929b0 in reap_plugins () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1343
            #27 0x0000aaaab6b93418 in plugin_shutdown () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:2051
            #28 0x0000aaaab6a9a1c8 in clean_up (print_message=print_message@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:1981
            #29 0x0000aaaab6aa54d4 in clean_up (print_message=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5864
            #30 mysqld_main (argc=141, argv=0xaaaac13cf730) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5931
            #31 0x0000ffff79650d64 in __libc_start_main () from /lib64/libc.so.6
            #32 0x0000aaaab6a98d00 in _start ()
            

            https://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-aarch64/builds/14266

            10.7 590ce857fee8d5807319c5448f0849fa60dc3b4c

            mariabackup.compression_providers_unloaded 'lzo' w3 [ fail ]  Found warnings/errors in server log file!
                    Test ended at 2022-08-24 13:18:07
            line
            220824 13:17:05 [ERROR] mysqld got signal 11 ;
            Attempting backtrace. You can use the following information to find out
            ^ Found warnings in /dev/shm/var/3/log/mysqld.1.err
            ok
             
             - found 'core.786' (0/0)
            #16 0x0000aaaab0029e58 in handle_fatal_signal (sig=11) at /usr/src/debug/MariaDB-/src_0/sql/signal_handler.cc:234
            #17 <signal handler called>
            #18 0x0000ffff90a5a8b8 in _int_free () from /lib64/libc.so.6
            #19 0x0000aaaab0468bc4 in aligned_free (ptr=0xaaaae59bc000) at /usr/src/debug/MariaDB-/src_0/include/aligned.h:37
            #20 0x0000aaaab046a33c in buf_pool_t::io_buf_t::close (this=0xaaaab0e6a848 <buf_pool+37832>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/include/buf0buf.h:1901
            #21 0x0000aaaab0463fe8 in buf_pool_t::close (this=0xaaaab0e61480 <buf_pool>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0buf.cc:1167
            #22 0x0000aaaab03e7364 in innodb_shutdown () at /usr/src/debug/MariaDB-/src_0/storage/innobase/srv/srv0start.cc:2055
            #23 0x0000aaaab02cff30 in innobase_end () at /usr/src/debug/MariaDB-/src_0/storage/innobase/handler/ha_innodb.cc:4377
            #24 0x0000aaaab002c5b0 in ha_finalize_handlerton (plugin=0xaaaae5093490) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:596
            #25 0x0000aaaaafe40308 in plugin_deinitialize (plugin=0xaaaae5093490, ref_check=ref_check@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1272
            #26 0x0000aaaaafe429b0 in reap_plugins () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1343
            #27 0x0000aaaaafe43418 in plugin_shutdown () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:2051
            #28 0x0000aaaaafd4a1c8 in clean_up (print_message=print_message@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:1981
            #29 0x0000aaaaafd554d4 in clean_up (print_message=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5864
            #30 mysqld_main (argc=144, argv=0xaaaae4eff730) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5931
            #31 0x0000ffff90a00d64 in __libc_start_main () from /lib64/libc.so.6
            #32 0x0000aaaaafd48d00 in _start ()
            

            marko Marko Mäkelä added a comment - There are some signs of memory corruption as well, in one particular environment: https://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-aarch64/builds/14264 10.7 bdd80e3fb1cb653c367099639bec46840eca86e1 plugins.compression 'innodb-lzo' w1 [ fail ] Found warnings/errors in server log file! Test ended at 2022-08-24 09:52:15 line 220824 9:51:12 [ERROR] mysqld got signal 11 ; Attempting backtrace. You can use the following information to find out ^ Found warnings in /dev/shm/var/1/log/mysqld.1.err ok   - found 'core.22329' (0/0) … #16 0x0000aaaab6d79e58 in handle_fatal_signal (sig=11) at /usr/src/debug/MariaDB-/src_0/sql/signal_handler.cc:234 #17 <signal handler called> #18 0x0000ffff796aa8b8 in _int_free () from /lib64/libc.so.6 #19 0x0000aaaab71b8bc4 in aligned_free (ptr=0xaaaac1e8c000) at /usr/src/debug/MariaDB-/src_0/include/aligned.h:37 #20 0x0000aaaab71ba33c in buf_pool_t::io_buf_t::close (this=0xaaaab7bba848 <buf_pool+37832>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/include/buf0buf.h:1901 #21 0x0000aaaab71b3fe8 in buf_pool_t::close (this=0xaaaab7bb1480 <buf_pool>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0buf.cc:1167 #22 0x0000aaaab7137364 in innodb_shutdown () at /usr/src/debug/MariaDB-/src_0/storage/innobase/srv/srv0start.cc:2055 #23 0x0000aaaab701ff30 in innobase_end () at /usr/src/debug/MariaDB-/src_0/storage/innobase/handler/ha_innodb.cc:4377 #24 0x0000aaaab6d7c5b0 in ha_finalize_handlerton (plugin=0xaaaac15634e0) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:596 #25 0x0000aaaab6b90308 in plugin_deinitialize (plugin=0xaaaac15634e0, ref_check=ref_check@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1272 #26 0x0000aaaab6b929b0 in reap_plugins () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1343 #27 0x0000aaaab6b93418 in plugin_shutdown () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:2051 #28 0x0000aaaab6a9a1c8 in clean_up (print_message=print_message@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:1981 #29 0x0000aaaab6aa54d4 in clean_up (print_message=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5864 #30 mysqld_main (argc=141, argv=0xaaaac13cf730) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5931 #31 0x0000ffff79650d64 in __libc_start_main () from /lib64/libc.so.6 #32 0x0000aaaab6a98d00 in _start () https://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-aarch64/builds/14266 10.7 590ce857fee8d5807319c5448f0849fa60dc3b4c mariabackup.compression_providers_unloaded 'lzo' w3 [ fail ] Found warnings/errors in server log file! Test ended at 2022-08-24 13:18:07 line 220824 13:17:05 [ERROR] mysqld got signal 11 ; Attempting backtrace. You can use the following information to find out ^ Found warnings in /dev/shm/var/3/log/mysqld.1.err ok   - found 'core.786' (0/0) … #16 0x0000aaaab0029e58 in handle_fatal_signal (sig=11) at /usr/src/debug/MariaDB-/src_0/sql/signal_handler.cc:234 #17 <signal handler called> #18 0x0000ffff90a5a8b8 in _int_free () from /lib64/libc.so.6 #19 0x0000aaaab0468bc4 in aligned_free (ptr=0xaaaae59bc000) at /usr/src/debug/MariaDB-/src_0/include/aligned.h:37 #20 0x0000aaaab046a33c in buf_pool_t::io_buf_t::close (this=0xaaaab0e6a848 <buf_pool+37832>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/include/buf0buf.h:1901 #21 0x0000aaaab0463fe8 in buf_pool_t::close (this=0xaaaab0e61480 <buf_pool>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0buf.cc:1167 #22 0x0000aaaab03e7364 in innodb_shutdown () at /usr/src/debug/MariaDB-/src_0/storage/innobase/srv/srv0start.cc:2055 #23 0x0000aaaab02cff30 in innobase_end () at /usr/src/debug/MariaDB-/src_0/storage/innobase/handler/ha_innodb.cc:4377 #24 0x0000aaaab002c5b0 in ha_finalize_handlerton (plugin=0xaaaae5093490) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:596 #25 0x0000aaaaafe40308 in plugin_deinitialize (plugin=0xaaaae5093490, ref_check=ref_check@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1272 #26 0x0000aaaaafe429b0 in reap_plugins () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:1343 #27 0x0000aaaaafe43418 in plugin_shutdown () at /usr/src/debug/MariaDB-/src_0/sql/sql_plugin.cc:2051 #28 0x0000aaaaafd4a1c8 in clean_up (print_message=print_message@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:1981 #29 0x0000aaaaafd554d4 in clean_up (print_message=true) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5864 #30 mysqld_main (argc=144, argv=0xaaaae4eff730) at /usr/src/debug/MariaDB-/src_0/sql/mysqld.cc:5931 #31 0x0000ffff90a00d64 in __libc_start_main () from /lib64/libc.so.6 #32 0x0000aaaaafd48d00 in _start ()

            CentOS 7 on ARMv8 has reached its end of life. The memory corruption issue could be specific to that platform, such as some bug in dlopen().

            marko Marko Mäkelä added a comment - CentOS 7 on ARMv8 has reached its end of life. The memory corruption issue could be specific to that platform, such as some bug in dlopen() .

            People

              serg Sergei Golubchik
              marko Marko Mäkelä
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.