Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.8.0, 10.7.1, 10.9.0
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
- is caused by
-
MDEV-12933 sort out the compression library chaos
-
- Closed
-
- relates to
-
MDEV-27339 Upgrade 10.5 -> 10.7 fails MariaDB tried to use the ... compression, but its provider plugin is not loaded
-
- Stalled
-
Activity
Field | Original Value | New Value |
---|---|---|
Link |
This issue is caused by |
Status | Open [ 1 ] | Confirmed [ 10101 ] |
Status | Confirmed [ 10101 ] | Open [ 1 ] |
Status | Open [ 1 ] | Needs Feedback [ 10501 ] |
Link | This issue relates to MDEV-27339 [ MDEV-27339 ] |
Status | Needs Feedback [ 10501 ] | Open [ 1 ] |
Status | Open [ 1 ] | Confirmed [ 10101 ] |
Priority | Critical [ 2 ] | Major [ 3 ] |
Fix Version/s | 10.7 [ 24805 ] |
Fix Version/s | 10.8 [ 26121 ] |
Fix Version/s | 10.11 [ 27614 ] |
Fix Version/s | 10.9 [ 26905 ] |
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]