[MDEV-28574] Assertion failure in fil_invalid_page_access_msg() while running CHECK TABLE to find the details on corruption suspected Created: 2022-05-16  Updated: 2023-01-12  Resolved: 2022-06-07

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: None
Fix Version/s: 10.6.9, 10.7.5, 10.8.4, 10.9.2

Type: Bug Priority: Major
Reporter: Valerii Kravchuk Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: crash

Issue Links:
Duplicate
duplicates MDEV-13542 Crashing on a corrupted page is unhel... Closed

 Description   

The following assertion failure happens (only partially resolved in the error log):

...
2022-05-14 14:26:38 6 [ERROR] [FATAL] InnoDB: Trying to read 16384 bytes at 7202668544 outside the bounds of the file: ./zimporter202205_ml_alto_7786517_db/t.ibd
220514 14:26:38 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
 
Server version: 10.6.7-MariaDB-log
key_buffer_size=134217728
read_buffer_size=262144
max_used_connections=2
max_threads=511
thread_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2368223 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7f0bd4000c58
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7f2609c3cc18 thread_stack 0x49000
/usr/sbin/mariadbd(my_print_stacktrace+0x2e)[0x55e12161db0e]
/usr/sbin/mariadbd(handle_fatal_signal+0x545)[0x55e121064825]
addr2line: DWARF error: could not find variable specification at offset 0x7067
addr2line: DWARF error: could not find variable specification at offset 0x155dd
/lib64/libpthread.so.0(+0x168c0)[0x7f262a2a18c0]
/lib64/libc.so.6(gsignal+0x10d)[0x7f262957ecdb]
/lib64/libc.so.6(abort+0x177)[0x7f2629580375]
/usr/sbin/mariadbd(+0xe4a918)[0x55e121530918]
/usr/sbin/mariadbd(+0xe0ec47)[0x55e1214f4c47]
addr2line: DWARF error: could not find variable specification at offset 0x7067
/usr/sbin/mariadbd(+0xdf8059)[0x55e1214de059]
/usr/sbin/mariadbd(+0xdce251)[0x55e1214b4251]
/usr/sbin/mariadbd(+0xdccaa8)[0x55e1214b2aa8]
/usr/sbin/mariadbd(+0xc8aead)[0x55e121370ead]
/usr/sbin/mariadbd(_ZN7handler8ha_checkEP3THDP15st_ha_check_opt+0x61)[0x55e12106d3e1]
fil/fil0fil.cc:2836(fil_space_t::io(IORequest const&, unsigned long, unsigned long, void*, buf_page_t*))[0x55e120f4dd6d]
addr2line: DWARF error: could not find variable specification at offset 0x11c6df
...
buf/buf0rea.cc:327(buf_read_page(page_id_t, unsigned long))[0x55e120f4ece8]
addr2line: DWARF error: could not find variable specification at offset 0x1df447
buf/buf0buf.cc:2596(buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool))[0x55e120e41c86]
addr2line: DWARF error: could not find variable specification at offset 0x1eb9db
...
include/btr0btr.h:212(btr_block_get(dict_index_t const&, unsigned int, unsigned long, bool, mtr_t*))[0x55e120e480a6]
btr/btr0btr.cc:4700(btr_validate_index(dict_index_t*, trx_t const*))[0x55e120e3d335]
addr2line: DWARF error: could not find variable specification at offset 0x1d68dd
...
/usr/sbin/mariadbd(_Z10do_commandP3THDb+0x12a)[0x55e120e3bfba]
handler/ha_innodb.cc:15232(ha_innobase::check(THD*, st_ha_check_opt*))[0x55e120f40187]
addr2line: DWARF error: could not find variable specification at offset 0x155dd
...
/usr/sbin/mariadbd(handle_one_connection+0x34)[0x55e120f40514]
sql/handler.cc:4928(handler::ha_check(THD*, st_ha_check_opt*))[0x55e1212a3e0d]
addr2line: DWARF error: could not find variable specification at offset 0x155dd
...
/lib64/libpthread.so.0(+0xa6ea)[0x7f262a2956ea]
/lib64/libc.so.6(clone+0x3f)[0x7f262964ba8f]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7f0bd40109c0): CHECK TABLE `t`
...

Core file was created and there we can see this full backtrace for the crashing thread:

#0  __GI_raise (sig=6) at ../sysdeps/unix/sysv/linux/raise.c:51
set = {__val = {552967, 18446744073709551615 <repeats 12 times>, 139801349301264, 139671653884496, 139801349300656}}
pid = <optimized out>
tid = <optimized out>
ret = <optimized out>
#1  0x00007f2629580324 in __GI_abort () at abort.c:100
act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {18446744073709551615 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x000055e121530918 in fil_invalid_page_access_msg (is_read=<optimized out>, len=94425522372776, offset=<optimized out>, name=<optimized out>, fatal=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/fil/fil0fil.cc:2765
No locals.
#3  fil_space_t::io (this=this@entry=0x55e127b7ff48, type=..., offset=<optimized out>, len=len@entry=16384, buf=<optimized out>, bpage=bpage@entry=0x7f17ec03eb20) at /usr/src/debug/MariaDB-/src_0/storage/innobase/fil/fil0fil.cc:2835
node = 0x55e127b800a8
p = <optimized out>
fatal = <optimized out>
err = <optimized out>
#4  0x000055e1214f4c47 in buf_read_page_low (unzip=false, zip_size=94425522372424, page_id=..., mode=132, sync=true, space=0x55e127b7ff48, err=<synthetic pointer>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0rea.cc:324
bpage = <optimized out>
dst = <optimized out>
len = <optimized out>
fio = <optimized out>
bpage = <optimized out>
dst = <optimized out>
len = <optimized out>
fio = <optimized out>
#5  buf_read_page (page_id=..., zip_size=zip_size@entry=0) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0rea.cc:470
space = 0x55e127b7ff48
err = DB_SUCCESS
#6  0x000055e1214de059 in buf_page_get_low (page_id=..., zip_size=<optimized out>, rw_latch=<optimized out>, guess=0x0, mode=10, mtr=<optimized out>, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0buf.cc:2596
local_err = <optimized out>
loop = <optimized out>
access_time = <optimized out>
retries = 0
chain = <optimized out>
hash_lock = <optimized out>
block = <optimized out>
state = <optimized out>
not_first_access = <optimized out>
#7  0x000055e1214df044 in buf_page_get_gen (page_id=..., zip_size=<optimized out>, rw_latch=<optimized out>, guess=guess@entry=0x0, mode=mode@entry=10, mtr=<optimized out>, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/buf/buf0buf.cc:3029
No locals.
#8  0x000055e1214b4251 in btr_block_get (index=..., page=<optimized out>, mode=<optimized out>, merge=<optimized out>, mtr=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/include/btr0btr.h:215
block = <optimized out>
err = DB_SUCCESS
#9  0x000055e1214b2aa8 in btr_validate_level (lockout=<optimized out>, level=<optimized out>, trx=<optimized out>, index=0x7f07d750a250) at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0btr.cc:4698
right_rec = <optimized out>
right_page = <optimized out>
cursor = <optimized out>
page = 0x7f17eda5c000 ""
right_block = <optimized out>
parent_right_page_no = <optimized out>
space = <optimized out>
left_page_no = 439614
right_node_cur = {index = 0x7f07d750a250, page_cur = {index = 0x32, rec = 0x7f206a2b98b0 "", offsets = 0x55e12137729f <ha_innobase::extra(ha_extra_function)+31>, block = 0x7f20640f3ac0}, purge_node = 0x7f07d74f8d80, left_block = 0x7f2609c3aa30, thr = 0x0, flag = BTR_CUR_BINARY, tree_height = 3, up_match = 0, up_bytes = 94425410082791, low_match = 1,  
low_bytes = 139671653812496, n_fields = 139671653847536, n_bytes = 139671653822904, fold = 139801349302832, path_arr = 0x53aeb529c6d4ce00, rtr_info = 0x0}
node_ptr_tuple = <optimized out>
heap = 0x7f07edd354f8
offsets2 = 0x0
savepoint = <optimized out>
savepoint2 = <optimized out>
right_page_no = 439616
block = 0x7f17ec03ec60
ret = true
mtr = {m_last = 0x0, m_last_offset = 0, m_log_mode = 0, m_modifications = 0, m_made_dirty = 1, m_inside_ibuf = 0, m_trim_pages = 0, m_memo = {m_heap = 0x0, m_list = {<ilist<mtr_buf_t::block_t, void>> = {sentinel_ = {next = 0x7f2609c3b068, prev = 0x7f2609c3b068}}, size_ = 1}, m_size = 48, m_first_block = {<ilist_node<void>> = {next = 0x7f2609c3b048,  
prev = 0x7f2609c3b048},  
m_data = "..."..., m_used = 48}}, m_log = {m_heap = 0x0, m_list = {<ilist<mtr_buf_t::block_t, void>> = {sentinel_ = {next = 0x7f2609c3b298, prev = 0x7f2609c3b298}}, size_ = 1}, m_size = 0, m_first_block = {<ilist_node<void>> = {next = 0x7f2609c3b278, prev = 0x7f2609c3b278},  
m_data = "..."..., m_used = 0}}, m_user_space = 0x0, m_commit_lsn = 0, m_freed_space = 0x0, m_freed_pages = 0x0}
parent_page_no = <optimized out>
father_page = <optimized out>
node_cur = {index = 0x7f07d750a250, page_cur = {index = 0x7f07d7500ed8, rec = 0x7f206a2b98a0 "", offsets = 0x7c8, block = 0x7f20640f3ac0}, purge_node = 0x55e121619dd4 <my_malloc+164>, left_block = 0x7f0bd4000020, thr = 0x0, flag = BTR_CUR_BINARY, tree_height = 3, up_match = 0, up_bytes = 139671653844744, low_match = 0, low_bytes = 139671653822904,  
n_fields = 139801349302656, n_bytes = 139801359012400, fold = 139688778140760, path_arr = 0x7f07d74f8d80, rtr_info = 0x0}
rec = <optimized out>
offsets = 0x0
rightmost_child = <optimized out>
node_ptr_fails = <optimized out>
loop = <optimized out>
block = <optimized out>
page = <optimized out>
right_block = <optimized out>
right_page = <optimized out>
father_page = <optimized out>
node_cur = <optimized out>
right_node_cur = <optimized out>
rec = <optimized out>
cursor = <optimized out>
node_ptr_tuple = <optimized out>
ret = <optimized out>
mtr = <optimized out>
heap = <optimized out>
offsets = <optimized out>
offsets2 = <optimized out>
savepoint = <optimized out>
savepoint2 = <optimized out>
parent_page_no = <optimized out>
parent_right_page_no = <optimized out>
rightmost_child = <optimized out>
space = <optimized out>
right_page_no = <optimized out>
left_page_no = <optimized out>
node_ptr = <optimized out>
left_page_no = <optimized out>
right_rec = <optimized out>
node_ptr = <optimized out>
first_rec = <optimized out>
right_node_ptr = <optimized out>
right_father_page = <optimized out>
#10 btr_validate_index (index=index@entry=0x7f07d750a250, trx=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/btr/btr0btr.cc:5019
i = <optimized out>
err = <optimized out>
lockout = <optimized out>
mtr = {m_last = 0x0, m_last_offset = 0, m_log_mode = 0, m_modifications = 0, m_made_dirty = 1, m_inside_ibuf = 0, m_trim_pages = 0, m_memo = {m_heap = 0x0, m_list = {<ilist<mtr_buf_t::block_t, void>> = {sentinel_ = {next = 0x7f2609c3abd8, prev = 0x7f2609c3abd8}}, size_ = 1}, m_size = 32, m_first_block = {<ilist_node<void>> = {next = 0x7f2609c3abb8, pr
ev = 0x7f2609c3abb8}, m_data = "...", m_used = 32}}, m_log = {m_heap = 0x0, m_list = {<ilist<mtr_buf_t::block_t, void>> = {sentinel_ = {next = 0x7f2609c3ae08, prev = 0x7f2609c3ae08}}, size_ = 1}, m_size = 0, m_first_block = {<ilist_node<void>> = {nex
t = 0x7f2609c3ade8, prev = 0x7f2609c3ade8}, m_data = ""..., m_used = 0}}, m_user_space = 0x0, m_commit_lsn = 0, m_freed_space = 0x0, m_freed_pages = 0x0}
root = <optimized out>
n = <optimized out>
#11 0x000055e121370ead in ha_innobase::check (this=0x7f07d74f8d80, thd=<optimized out>, check_opt=0x7f0bd4006098) at /usr/src/debug/MariaDB-/src_0/storage/innobase/handler/ha_innodb.cc:15230
err = <optimized out>
index = 0x7f07d750a250
n_rows = 94425407591421
n_rows_in_table = 18446744073709551615
is_ok = true
ret = <optimized out>
old_isolation_level = <optimized out>
#12 0x000055e12106d3e1 in handler::ha_check (this=0x7f07d74f8d80, thd=0x7f0bd4000c58, check_opt=<optimized out>) at /usr/src/debug/MariaDB-/src_0/sql/handler.cc:4928
error = <optimized out>
#13 0x000055e120f4dd6d in mysql_admin_table (thd=thd@entry=0x7f0bd4000c58, tables=tables@entry=0x7f0bd4010ac8, check_opt=check_opt@entry=0x7f0bd4006098, operator_name=operator_name@entry=0x55e121ecf1e0 <msg_check>, lock_type=lock_type@entry=TL_READ_NO_INSERT, org_open_for_modify=org_open_for_modify@entry=false, repair_table_use_frm=false, extra_open_options=3
2, prepare_func=0x0, operator_func=<optimized out>, view_operator_func=0x55e120f03310 <view_check(THD*, TABLE_LIST*, st_ha_check_opt*)>, is_cmd_replicated=false) at /usr/src/debug/MariaDB-/src_0/sql/sql_admin.cc:875
table_name_buff = "db.t\000roup_junc\000..."...
tabledef_version_buff = "10\000\t&\177\000\000\250#\001\324\v\177\000"
db = <optimized out>
fatal_error = false
open_error = <optimized out>
storage_engine_partitioned = false
open_for_modify = false
table_name = <optimized out>
storage_engine_name = "..."
collect_eis = <optimized out>
err = <optimized out>
table = 0x7f0bd4010ac8
field_list = {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x7f0bd4011260, last = 0x7f0bd4011428, elements = 4}, <No data fields>}
protocol = <optimized out>
lex = 0x7f0bd4004d38
result_code = 0
compl_result_code = 0
need_repair_or_alter = false
suspended_wfc = <optimized out>
is_table_modified = false
tabledef_version = {str = 0x7f2609c3b710 "10", length = 139688778205645}
#14 0x000055e120f4ece8 in Sql_cmd_check_table::execute (this=<optimized out>, thd=0x7f0bd4000c58) at /usr/src/debug/MariaDB-/src_0/sql/sql_admin.cc:1486
m_lex = 0x7f0bd4004d38
first_table = 0x7f0bd4010ac8
lock_type = TL_READ_NO_INSERT
res = true
#15 0x000055e120e41c86 in mysql_execute_command (thd=thd@entry=0x7f0bd4000c58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:5996
wsrep_error_label = <optimized out>
error = <optimized out>
res = 0
up_result = 0
lex = 0x7f0bd4004d38
select_lex = <optimized out>
first_table = 0x7f0bd4010ac8
all_tables = 0x7f0bd4010ac8
unit = 0x7f0bd4004e00
have_table_map_for_update = false
rpl_filter = <optimized out>
ots = {ctx = 0x7f0bd40049e8, traceable = false}
orig_binlog_format = BINLOG_FORMAT_MIXED
orig_current_stmt_binlog_format = BINLOG_FORMAT_STMT
#16 0x000055e120e480a6 in mysql_parse (thd=0x7f0bd4000c58, rawbuf=<optimized out>, length=23, parser_state=0x7f2609c3c310) at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:8029
found_semicolon = <optimized out>
error = <optimized out>
lex = 0x7f0bd4004d38
err = <optimized out>
#17 0x000055e120e3d335 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f0bd4000c58, packet=packet@entry=0x7f0bd4008569 "", packet_length=packet_length@entry=24, blocking=blocking@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:1896
packet_end = 0x7f0bd40109d7 ""
parser_state = {m_lip = {lookahead_token = -1, lookahead_yylval = 0x0, m_thd = 0x7f0bd4000c58, m_ptr = 0x7f0bd40109d8 ")", m_tok_start = 0x7f0bd40109d8 ")", m_tok_end = 0x7f0bd40109d8 ")", m_end_of_query = 0x7f0bd40109d7 "", m_tok_start_prev = 0x7f0bd40109d7 "", m_buf = 0x7f0bd40109c0 "CHECK TABLE `t`", m_buf_length = 23, m_echo = true, m_echo
_saved = true, m_cpp_buf = 0x7f0bd4010a58 "CHECK TABLE `t`", m_cpp_ptr = 0x7f0bd4010a6f "", m_cpp_tok_start = 0x7f0bd4010a6f "", m_cpp_tok_start_prev = 0x7f0bd4010a6f "", m_cpp_tok_end = 0x7f0bd4010a6f "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x0, m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_END, found_semicolon = 0x0, ignore_space = false, stm
t_prepare_mode = false, multi_statements = true, yylineno = 1, m_digest = 0x0, in_comment = NO_COMMENT, in_comment_saved = NO_COMMENT, m_cpp_text_start = 0x7f0bd4010a65 "en_output`", m_cpp_text_end = 0x7f0bd4010a6e "`", m_underscore_cs = 0x0}, m_yacc = {yacc_yyss = 0x0, yacc_yyvs = 0x0, m_set_signal_info = {m_item = {0x0 <repeats 12 times>}}, m_lock_type = TL
_UNLOCK, m_mdl_type = MDL_SHARED_READ}, m_digest_psi = 0x0}
net = 0x7f0bd4000ee8
error = false
do_end_of_statement = true
drop_more_results = false
__FUNCTION__ = "dispatch_command"
res = <optimized out>
#18 0x000055e120e3bfba in do_command (thd=0x7f0bd4000c58, blocking=blocking@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_parse.cc:1404
return_value = <optimized out>
packet = 0x7f0bd4008568 "\002"
packet_length = <optimized out>
net = 0x7f0bd4000ee8
command = COM_QUERY
__FUNCTION__ = "do_command"
#19 0x000055e120f40187 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55e128379508, put_in_cache=put_in_cache@entry=true) at /usr/src/debug/MariaDB-/src_0/sql/sql_connect.cc:1418
create_user = true
thr_create_utime = <optimized out>
thd = 0x7f0bd4000c58
#20 0x000055e120f40514 in handle_one_connection (arg=arg@entry=0x55e128379508) at /usr/src/debug/MariaDB-/src_0/sql/sql_connect.cc:1312
connect = 0x55e128379508
#21 0x000055e1212a3e0d in pfs_spawn_thread (arg=0x55e1282fa868) at /usr/src/debug/MariaDB-/src_0/storage/perfschema/pfs.cc:2201
typed_arg = 0x55e1282fa868
user_arg = 0x55e128379508
user_start_routine = 0x55e120f404e0 <handle_one_connection(void*)>
pfs = <optimized out>
klass = <optimized out>
#22 0x00007f262a2956ea in start_thread (arg=0x7f2609c3d700) at pthread_create.c:477

SELECT * FROM t also ends with assertion failure with this top of the full backtrace:

...
#1  0x00007f3cb600e324 in __GI_abort () at abort.c:100
act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {18446744073709551615 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00005635f67a5918 in fil_invalid_page_access_msg (is_read=<optimized out>, len=94789875681832, offset=<optimized out>, name=<optimized out>, fatal=<optimized out>) at /usr/src/debug/MariaDB-/src_0/storage/innobase/fil/fil0fil.cc:2765
No locals.
#3  fil_space_t::io (this=this@entry=0x5635fcde48c8, type=..., offset=<optimized out>, len=len@entry=16384, buf=<optimized out>, bpage=bpage@entry=0x7f3bb0054ba0) at /usr/src/debug/MariaDB-/src_0/storage/innobase/fil/fil0fil.cc:2835
node = 0x5635fcde4a28
p = <optimized out>
fatal = <optimized out>
err = <optimized out>
...

We need a way for CHECK TABLE to report something about the problem without crashing the server in such an unexpected manner.



 Comments   
Comment by Marko Mäkelä [ 2022-05-16 ]

I believe that this particular case is already fixed in the bb-10.6-MDEV-13542 branch which is under testing. We are stress testing it with fault injection, and the objective is to avoid any crashes when a corrupted page is read or an out-of-bounds page read is attempted. Some corruption (such as corruption triggered during the change buffer merge, which can be triggered during CHECK TABLE) may still crash the server.

Generated at Thu Feb 08 10:01:47 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.