[MDEV-23456] fil_space_crypt_t::write_page0() is accessing an uninitialized page - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.2.35, 10.3.26, 10.4.16, 10.5.7
Component/s: Storage Engine - InnoDB
Labels:

Description

This bug was repeated with the test case of ~~MDEV-17596~~, which was originally filed about something else. Here is the .opt file:

--innodb-encrypt-tables=ON

--innodb-encryption-threads=4

--innodb-log-optimize-ddl=OFF

And here the .test file:

--source include/have_innodb.inc

--source include/have_file_key_management_plugin.inc

SET @scrub.save= @@innodb_background_scrub_data_uncompressed;

--connect (con1,localhost,root,,)

CREATE TABLE t1 (pk INT, a INT, PRIMARY KEY(pk)) ENGINE=InnoDB;

INSERT INTO t1 VALUES (1,2),(2,3),(3,4),(4,5),(5,6),(6,7),(7,8),(8,9);

SET GLOBAL innodb_background_scrub_data_uncompressed=ON;

--disconnect con1

--connection default

--let $i= 1000

while ($i)

   --eval ALTER TABLE t1 FORCE /* $i */

   --dec $i

# Cleanup

--delimiter ;

DROP TABLE t1;

EOF

With a small tweak, I got an rr replay trace:

diff --git a/mysql-test/lib/My/SafeProcess/safe_process.cc b/mysql-test/lib/My/SafeProcess/safe_process.cc

index 13d09198a0c..1a20f5ad748 100644

--- a/mysql-test/lib/My/SafeProcess/safe_process.cc

+++ b/mysql-test/lib/My/SafeProcess/safe_process.cc

@@ -97,7 +97,7 @@ static int kill_child(bool was_killed)

   message("Killing child: %d", child_pid);

   // Terminate whole process group

   if (! was_killed)

-    kill(-child_pid, SIGKILL);

+    kill(-child_pid, SIGABRT);

   pid_t ret_pid= waitpid(child_pid, &status, 0);

   if (ret_pid == child_pid)

The page was freed earlier, and it had been reallocated to a new page 0 of an encrypted tablespace, but the initialization of that page frame was still in progress at the time of invoking fil_space_crypt_t::write_page0():

10.2 01738d08f30315f10c14faa605d0087e54156cd0
Thread 11 hit Hardware watchpoint 1: -location page[4]@4

Old value = "\000\000\001}"
New value = "\377\377\377\377"
buf_LRU_block_remove_hashed (bpage=0x644315d20900, zip=true) at /mariadb/10.2o/storage/innobase/buf/buf0lru.cc:1860
1860 memset(((buf_block_t*) bpage)->frame
(rr) when
Current event: 1220914
(rr) bt
#0 0x000055f5c18afa43 in buf_LRU_block_remove_hashed (bpage=0x644315d20900, zip=true) at /mariadb/10.2o/storage/innobase/buf/buf0lru.cc:1858
#1 0x000055f5c18ae113 in buf_LRU_free_page (bpage=0x644315d20900, zip=true) at /mariadb/10.2o/storage/innobase/buf/buf0lru.cc:1476
#2 0x000055f5c18a267d in buf_flush_LRU_list_batch (buf_pool=<optimized out>, max=100, n=<optimized out>) at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:1656
#3 0x000055f5c18a3c84 in buf_do_LRU_batch (buf_pool=0x55f5c2df4780, max=100, n=0x30ec25dbcb40) at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:1727
#4 buf_flush_batch (buf_pool=<optimized out>, flush_type=<optimized out>, min_n=100, lsn_limit=0, n=0x55f5c2e44d40) at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:1855
#5 0x000055f5c18a7d86 in buf_flush_do_batch (type=BUF_FLUSH_LRU, min_n=100, lsn_limit=0, n=0x30ec25dbcb40, buf_pool=<optimized out>) at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:2028
#6 buf_flush_LRU_list (buf_pool=<optimized out>) at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:2299
#7 pc_flush_slot () at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:2820
#8 0x000055f5c18a60d5 in buf_flush_page_cleaner_coordinator () at /mariadb/10.2o/storage/innobase/buf/buf0flu.cc:3256
#9 0x000057bc2d6e0ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
#10 0x00007fdd4f3abeaf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr) c
Continuing.

Thread 11 hit Hardware watchpoint 2: -location block.page.id

Old value = {m_space = 0, m_page_no = 381}
New value = {m_space = 4294967295, m_page_no = 4294967295}
buf_LRU_block_free_hashed_page (block=0x644315d20900) at /mariadb/10.2o/storage/innobase/buf/buf0lru.cc:1943
1943 buf_block_set_state(block, BUF_BLOCK_MEMORY);
(rr) when
Current event: 1220920
(rr) c
Continuing.

Thread 11 hit Hardware watchpoint 1: -location page[4]@4

Old value = "\377\377\377\377"
New value = "\376\376\376\376"
buf_LRU_block_free_non_file_page (block=0x644315d20900) at /mariadb/10.2o/storage/innobase/buf/buf0lru.cc:1666
1666 memset(block->frame + FIL_PAGE_ARCH_LOG_NO_OR_SPACE_ID, 0xfe, 4);
(rr) c
Continuing.
[Switching to Thread 33579.33908]

Thread 32 hit Hardware watchpoint 2: -location block.page.id

Old value = {m_space = 4294967295, m_page_no = 4294967295}
New value = {m_space = 86, m_page_no = 0}
buf_page_init (buf_pool=0x55f5c2df4780, page_id={m_space = 86, m_page_no = 0}, page_size=@0x7faf707e9248: {m_physical = 16384, m_logical = 16384, m_is_compressed = 0}, block=0x644315d20900)
at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:5261
5261 buf_block_init_low(block);
(rr) bt
#0 buf_page_init (buf_pool=0x55f5c2df4780, page_id={m_space = 86, m_page_no = 0}, page_size=@0x7faf707e9248: {m_physical = 16384, m_logical = 16384, m_is_compressed = 0}, block=0x644315d20900)
at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:5261
#1 0x000055f5c188f50b in buf_page_create (page_id=<optimized out>, page_size=@0x7faf707e9248: {m_physical = 16384, m_logical = 16384, m_is_compressed = 0}, mtr=0x7faf707e92d8)
at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:5634
#2 0x000055f5c1926011 in fsp_header_init (space_id=86, size=4, mtr=0x7faf707e92d8) at /mariadb/10.2o/storage/innobase/fsp/fsp0fsp.cc:703
#3 0x000055f5c18c064c in dict_build_table_def_step (thr=0x7faf680d8e18, node=0x7faf6813aec0) at /mariadb/10.2o/storage/innobase/dict/dict0crea.cc:443
#4 dict_create_table_step (thr=0x7faf680d8e18) at /mariadb/10.2o/storage/innobase/dict/dict0crea.cc:1321
#5 0x000055f5c17209db in que_thr_step (thr=0x7faf680d8e18) at /mariadb/10.2o/storage/innobase/que/que0que.cc:1050
#6 que_run_threads_low (thr=0x7faf680d8e18) at /mariadb/10.2o/storage/innobase/que/que0que.cc:1104
#7 que_run_threads (thr=<optimized out>) at /mariadb/10.2o/storage/innobase/que/que0que.cc:1144
#8 0x000055f5c1765e1f in row_create_table_for_mysql (table=<optimized out>, trx=0x22ef1f780268, mode=FIL_ENCRYPTION_DEFAULT, key_id=<optimized out>) at /mariadb/10.2o/storage/innobase/row/row0mysql.cc:2273
#9 0x000055f5c166f692 in prepare_inplace_alter_table_dict (ha_alter_info=0x7faf707ed730, altered_table=0x7faf680d8088, old_table=0x7faf680c3de8, table_name=0x7faf680d1fc5 "t1", flags=33,
flags2=<optimized out>, fts_doc_id_col=<optimized out>, add_fts_doc_id=false, add_fts_doc_id_idx=<optimized out>) at /mariadb/10.2o/storage/innobase/handler/handler0alter.cc:4711
#10 0x000055f5c166afd2 in ha_innobase::prepare_inplace_alter_table (this=<optimized out>, altered_table=<optimized out>, ha_alter_info=0x7faf707ed730)
at /mariadb/10.2o/storage/innobase/handler/handler0alter.cc:6048
#11 0x000055f5c1358032 in mysql_inplace_alter_table (thd=0x7faf68000d28, table_list=0x7faf68011a58, table=0x7faf680c3de8, altered_table=0x7faf680d8088, ha_alter_info=0x7faf707ed730,
inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=<optimized out>, alter_ctx=0x7faf707ec970) at /mariadb/10.2o/sql/sql_table.cc:7420
#12 mysql_alter_table (thd=<optimized out>, new_db=<optimized out>, new_name=<optimized out>, create_info=<optimized out>, table_list=0x7faf68011a58, alter_info=<optimized out>, order_num=<optimized out>,
order=<optimized out>, ignore=<optimized out>) at /mariadb/10.2o/sql/sql_table.cc:9622
#13 0x000055f5c13b1818 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7faf68000d28) at /mariadb/10.2o/sql/sql_alter.cc:333
#14 0x000055f5c12b5796 in mysql_execute_command (thd=0x7faf68000d28) at /mariadb/10.2o/sql/sql_parse.cc:5964
#15 0x000055f5c12b2e14 in mysql_parse (thd=0x7faf68000d28, rawbuf=0x7faf68011970 "ALTER TABLE t1 FORCE /* 919 */", length=<optimized out>, parser_state=0x7faf707ef6d0, is_com_multi=<optimized out>,
is_next_command=false) at /mariadb/10.2o/sql/sql_parse.cc:7733
…
(rr) c
Continuing.

Thread 3 received signal SIGABRT, Aborted.
[Switching to Thread 33579.33881]
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
50 ../sysdeps/unix/sysv/linux/raise.c: Tiedostoa tai hakemistoa ei ole.
(rr) f 8
#8 0x000055f5c191e56f in fil_space_crypt_t::write_page0 (this=0x7faf680b0ca0, space=0x7faf680722e0, page=0x6443160a8000 "\351<\376\247\376\376\376\376\377\377\377\377\377\377\377\377", mtr=0x663c7a2b32d8)
at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:398
398 mlog_write_string(page + offset, CRYPT_MAGIC, MAGIC_SZ, mtr);
(rr) p *space
$3 = {<ilist_node<unflushed_spaces_tag_t>> = {next = 0x0, prev = 0x0}, <ilist_node<rotation_list_tag_t>> = {next = 0x0, prev = 0x0}, id = 86, hash = 0x0, name = 0x7faf68081fb0 "test/#sql-832b_9",
…
(rr) up
#9 0x000055f5c1922b21 in fil_crypt_flush_space (state=<optimized out>) at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:2069
2069 crypt_data->write_page0(space, block->frame, &mtr);
(rr)
#10 fil_crypt_complete_rotate_space (key_state=<optimized out>, state=<optimized out>) at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:2150
2150 fil_crypt_flush_space(state);
(rr)
#11 0x000055f5c1921af4 in fil_crypt_thread () at /mariadb/10.2o/storage/innobase/fil/fil0crypt.cc:2254
2254 fil_crypt_complete_rotate_space(&new_state, &thr);
(rr) thr 32
…
(rr) thr bt
…
#5 0x000055f5c17dd24b in rw_lock_debug_mutex_enter () at /mariadb/10.2o/storage/innobase/sync/sync0debug.cc:1264
#6 0x000055f5c17d75a9 in rw_lock_own (lock=0x55f5c2e47928, lock_type=5) at /mariadb/10.2o/storage/innobase/sync/sync0rw.cc:1009
#7 0x000055f5c1884361 in buf_page_hash_get_low (buf_pool=0x55f5c2df4780, page_id=<optimized out>) at /mariadb/10.2o/storage/innobase/include/buf0buf.ic:1117
#8 0x000055f5c18877ee in buf_page_get_low (page_id={m_space = 86, m_page_no = 0}, page_size=@0x7faf707e9248: {m_physical = 16384, m_logical = 16384, m_is_compressed = 0}, rw_latch=4, guess=0x0,
mode=<optimized out>, file=0x55f5c1cd9678 "/mariadb/10.2o/storage/innobase/fsp/fsp0fsp.cc", line=704, mtr=0x7faf707e92d8, err=0x0) at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:4309
#9 0x000055f5c188b481 in buf_page_get_gen (page_id=<optimized out>, page_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, file=<optimized out>, line=327713,
mtr=0x7faf680d8e18, err=0x0) at /mariadb/10.2o/storage/innobase/buf/buf0buf.cc:4907
#10 0x000055f5c1926042 in fsp_header_init (space_id=86, size=4, mtr=0x7faf707e92d8) at /mariadb/10.2o/storage/innobase/fsp/fsp0fsp.cc:704

So, the page was freed and then reused for something else. We can see that fil_space_crypt_t::write_page0() is accessing page 86:0, which has not been initialized yet by fsp_header_init().

I think that to fix this remaining bug, we should not allow fil_crypt_thread to access tablespaces whose first page has not been initialized yet. This bug should affect 10.5 as well, even though no assertion should fail there. In 10.5, we could be writing redo log for a not-yet-initialized page 0, but thanks to ~~MDEV-12353~~ we should get the correct page number straight from the buf_page_t.

Attachments

Issue Links

causes

MDEV-24188 Hang in buf_page_create() after reusing a previously freed page

Closed

duplicates

MDEV-23260 Draft: Crash when running encryption.innodb-encryption-alter-cbc,innodb

Closed

relates to

MDEV-17339 encryption.innodb_encryption_tables failed in buildbot, server crashed on restart

Closed

MDEV-17596 Assertion `block->page.flush_observer == __null || block->page.flush_observer == observer' failed in buf_flush_note_modification

Closed

MDEV-23452 Assertion `buf_page_get_io_fix(bpage) == BUF_IO_NONE' failed in buf_page_set_sticky

Closed

Activity

People

Assignee:: Thirunarayanan Balathandayuthapani

Reporter:: Marko Mäkelä

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2020-08-12 08:47

Updated:: 2020-11-13 18:16

Resolved:: 2020-09-09 06:30

Git Integration

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