[MDEV-25385] Server crash or assertion `file != ((void *)0)' failure in translog_sync_files Created: 2021-04-11  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Encryption, Locking, Storage Engine - Aria
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Unresolved Votes: 0
Labels: None

Attachments: HTML File threads_10_5e_debug     HTML File threads_10_5e_rel     HTML File threads_full_10_2_debug     HTML File threads_full_10_5_debug    
Issue Links:
Relates
relates to MDEV-17225 Assertion `log_descriptor.bc.buffer->... Open

 Description   

I get these failures on all versions and different builds, although some versions and builds are more willing to reproduce it than others.
However, so far I can't come up with a general test which would work (fail) on all versions. There are some unreliable version-specific variants which employ backup stages (the failure on 10.2 below shows that it's not limited to backup stages).

10.2 bf1e09e0 debug,

 
mysqld: /home/elenst/src/10.2/storage/maria/ma_loghandler.c:7882: translog_sync_files: Assertion `file != ((void *)0)' failed.
 
210411 11:36:59 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f5267aa20d2 in __assert_fail () from /lib64/libc.so.6
 
#8  0x000055b391b84445 in translog_sync_files (min=1, max=2619214, sync_dir=0 '\000') at /home/elenst/src/10.2/storage/maria/ma_loghandler.c:7882
 
#9  0x000055b391b850dd in translog_flush (lsn=11249439983363622) at /home/elenst/src/10.2/storage/maria/ma_loghandler.c:8199
 
#10 0x000055b391b9ecef in maria_flush_log_for_page (args=0x7f525009b4d0) at /home/elenst/src/10.2/storage/maria/ma_pagecrc.c:376
 
#11 0x000055b391b87e76 in pagecache_fwrite (pagecache=0x55b393136a60 <maria_pagecache_var>, filedesc=0x7f5251a23418, buffer=0x7f52529d0080 "N\367'&f!Z", pageno=2, type=PAGECACHE_LSN_PAGE, flags=36) at /home/elenst/src/10.2/storage/maria/ma_pagecache.c:660
 
#12 0x000055b391b9193c in flush_cached_blocks (pagecache=0x55b393136a60 <maria_pagecache_var>, file=0x7f51b01ebce0, cache=0x7f525009b6e0, end=0x7f525009b710, type=FLUSH_RELEASE, first_errno=0x7f525009b644) at /home/elenst/src/10.2/storage/maria/ma_pagecache.c:4419
 
#13 0x000055b391b922e6 in flush_pagecache_blocks_int (pagecache=0x55b393136a60 <maria_pagecache_var>, file=0x7f51b01ebce0, type=FLUSH_RELEASE, filter=0x0, filter_arg=0x0) at /home/elenst/src/10.2/storage/maria/ma_pagecache.c:4715
 
#14 0x000055b391b92705 in flush_pagecache_blocks_with_filter (pagecache=0x55b393136a60 <maria_pagecache_var>, file=0x7f51b01ebce0, type=FLUSH_RELEASE, filter=0x0, filter_arg=0x0) at /home/elenst/src/10.2/storage/maria/ma_pagecache.c:4832
 
#15 0x000055b391be8d2e in maria_close (info=0x7f51b07fc840) at /home/elenst/src/10.2/storage/maria/ma_close.c:49
 
#16 0x000055b391b64aba in ha_maria::close (this=0x7f51b01e9328) at /home/elenst/src/10.2/storage/maria/ha_maria.cc:1277
 
#17 0x000055b3915965f1 in handler::ha_close (this=0x7f51b01e9328) at /home/elenst/src/10.2/sql/handler.cc:2657
 
#18 0x000055b391417bfa in closefrm (table=0x7f51b01e8720) at /home/elenst/src/10.2/sql/table.cc:3525
 
#19 0x000055b391506f01 in intern_close_table (table=0x7f51b01e8720) at /home/elenst/src/10.2/sql/table_cache.cc:222
 
#20 0x000055b391507308 in tc_purge (mark_flushed=true) at /home/elenst/src/10.2/sql/table_cache.cc:335
 
#21 0x000055b3912963de in close_cached_tables (thd=0x7f51c4000af0, tables=0x0, wait_for_refresh=true, timeout=10) at /home/elenst/src/10.2/sql/sql_base.cc:374
 
#22 0x000055b39149afa9 in reload_acl_and_cache (thd=0x7f51c4000af0, options=4, tables=0x0, write_to_binlog=0x7f525009fc10) at /home/elenst/src/10.2/sql/sql_reload.cc:344
 
#23 0x000055b391312061 in mysql_execute_command (thd=0x7f51c4000af0) at /home/elenst/src/10.2/sql/sql_parse.cc:5201
 
#24 0x000055b391319775 in mysql_parse (thd=0x7f51c4000af0, rawbuf=0x7f51c40132e8 "FLUSH /* QNO 1291 CON_ID 25 */ TABLES", length=37, parser_state=0x7f52500a0520, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2/sql/sql_parse.cc:7794
 
#25 0x000055b391307a5e in dispatch_command (command=COM_QUERY, thd=0x7f51c4000af0, packet=0x7f51c40088b1 "FLUSH /* QNO 1291 CON_ID 25 */ TABLES", packet_length=37, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.2/sql/sql_parse.cc:1828
 
#26 0x000055b391306404 in do_command (thd=0x7f51c4000af0) at /home/elenst/src/10.2/sql/sql_parse.cc:1382
 
#27 0x000055b39145fef6 in do_handle_one_connection (connect=0x55b394272580) at /home/elenst/src/10.2/sql/sql_connect.cc:1336
 
#28 0x000055b39145fc41 in handle_one_connection (arg=0x55b394272580) at /home/elenst/src/10.2/sql/sql_connect.cc:1241
 
#29 0x00007f52697b4dd5 in start_thread () from /lib64/libpthread.so.0
 
#30 0x00007f5267b70ead in clone () from /lib64/libc.so.6

all threads for the above: threads_full_10_2_debug

10.5 2e67b9f6 debug

 
mysqld: /home/elenst/src/10.5/storage/maria/ma_loghandler.c:7888: translog_sync_files: Assertion `file != ((void *)0)' failed.
 
210327  1:58:59 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fa224c30252 in __assert_fail () from /lib64/libc.so.6
 
#8  0x00005559cb342389 in translog_sync_files (min=1, max=4161181, sync_dir=0 '\000') at /home/elenst/src/10.5/storage/maria/ma_loghandler.c:7888
 
#9  0x00005559cb343265 in translog_flush (lsn=17872137156560647) at /home/elenst/src/10.5/storage/maria/ma_loghandler.c:8233
 
#10 0x00005559cb3621fe in maria_flush_log_for_page (args=0x7fa20c0662c0) at /home/elenst/src/10.5/storage/maria/ma_pagecrc.c:375
 
#11 0x00005559cb346746 in pagecache_fwrite (pagecache=0x5559cd1ca940 <maria_pagecache_var>, filedesc=0x7fa22194c670, buffer=0x7fa20ec45000 "\235~?\a\a\230\062", pageno=1, type=PAGECACHE_LSN_PAGE, flags=36) at /home/elenst/src/10.5/storage/maria/ma_pagecache.c:675
 
#12 0x00005559cb353d47 in flush_cached_blocks (pagecache=0x5559cd1ca940 <maria_pagecache_var>, file=0x7fa1a053f760, cache=0x7fa20c0664d0, end=0x7fa20c066558, type=FLUSH_RELEASE, first_errno=0x7fa20c066434) at /home/elenst/src/10.5/storage/maria/ma_pagecache.c:4815
 
#13 0x00005559cb35485b in flush_pagecache_blocks_int (pagecache=0x5559cd1ca940 <maria_pagecache_var>, file=0x7fa1a053f760, type=FLUSH_RELEASE, filter=0x0, filter_arg=0x0) at /home/elenst/src/10.5/storage/maria/ma_pagecache.c:5111
 
#14 0x00005559cb354cab in flush_pagecache_blocks_with_filter (pagecache=0x5559cd1ca940 <maria_pagecache_var>, file=0x7fa1a053f760, type=FLUSH_RELEASE, filter=0x0, filter_arg=0x0) at /home/elenst/src/10.5/storage/maria/ma_pagecache.c:5226
 
#15 0x00005559cb312b95 in maria_close (info=0x7fa1a00fb4e8) at /home/elenst/src/10.5/storage/maria/ma_close.c:52
 
#16 0x00005559cb31cb2f in ha_maria::close (this=0x7fa1a05edd70) at /home/elenst/src/10.5/storage/maria/ha_maria.cc:1243
 
#17 0x00005559cb08c5a7 in handler::ha_close (this=0x7fa1a05edd70) at /home/elenst/src/10.5/sql/handler.cc:3053
 
#18 0x00005559cae63750 in closefrm (table=0x7fa1a06db698) at /home/elenst/src/10.5/sql/table.cc:4322
 
#19 0x00005559cafadd55 in intern_close_table (table=0x7fa1a06db698) at /home/elenst/src/10.5/sql/table_cache.cc:220
 
#20 0x00005559cafae17c in tc_purge () at /home/elenst/src/10.5/sql/table_cache.cc:312
 
#21 0x00005559cac6c6d1 in purge_tables () at /home/elenst/src/10.5/sql/sql_base.cc:327
 
#22 0x00005559cac6c85c in close_cached_tables (thd=0x7fa1b0000b18, tables=0x0, wait_for_refresh=true, timeout=10) at /home/elenst/src/10.5/sql/sql_base.cc:356
 
#23 0x00005559caf0b56b in reload_acl_and_cache (thd=0x7fa1b0000b18, options=4, tables=0x0, write_to_binlog=0x7fa20c06a9e0) at /home/elenst/src/10.5/sql/sql_reload.cc:336
 
#24 0x00005559cad2278d in mysql_execute_command (thd=0x7fa1b0000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:5515
 
#25 0x00005559cac23a49 in sp_instr_stmt::exec_core (this=0x7fa1b00c1cd8, thd=0x7fa1b0000b18, nextp=0x7fa20c06af4c) at /home/elenst/src/10.5/sql/sp_head.cc:3768
 
#26 0x00005559cac22d99 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fa1b00c1d20, thd=0x7fa1b0000b18, nextp=0x7fa20c06af4c, open_tables=false, instr=0x7fa1b00c1cd8) at /home/elenst/src/10.5/sql/sp_head.cc:3495
 
#27 0x00005559cac235c1 in sp_instr_stmt::execute (this=0x7fa1b00c1cd8, thd=0x7fa1b0000b18, nextp=0x7fa20c06af4c) at /home/elenst/src/10.5/sql/sp_head.cc:3674
 
#28 0x00005559cac1ccda in sp_head::execute (this=0x7fa1b00c1080, thd=0x7fa1b0000b18, merge_da_on_success=true) at /home/elenst/src/10.5/sql/sp_head.cc:1437
 
#29 0x00005559cac1fac5 in sp_head::execute_procedure (this=0x7fa1b00c1080, thd=0x7fa1b0000b18, args=0x7fa1b0005ba8) at /home/elenst/src/10.5/sql/sp_head.cc:2449
 
#30 0x00005559cad19e5a in do_execute_sp (thd=0x7fa1b0000b18, sp=0x7fa1b00c1080) at /home/elenst/src/10.5/sql/sql_parse.cc:3088
 
#31 0x00005559cad1aa84 in Sql_cmd_call::execute (this=0x7fa1b0013b48, thd=0x7fa1b0000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:3334
 
#32 0x00005559cad24818 in mysql_execute_command (thd=0x7fa1b0000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:6049
 
#33 0x00005559cad2a6ff in mysql_parse (thd=0x7fa1b0000b18, rawbuf=0x7fa1b0013a70 "CALL /* QNO 2511 CON_ID 18 */ sp4", length=33, parser_state=0x7fa20c06c3e0, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:8093
 
#34 0x00005559cad16737 in dispatch_command (command=COM_QUERY, thd=0x7fa1b0000b18, packet=0x7fa1b000b179 "CALL /* QNO 2511 CON_ID 18 */ sp4", packet_length=33, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.5/sql/sql_parse.cc:1890
 
#35 0x00005559cad14dab in do_command (thd=0x7fa1b0000b18) at /home/elenst/src/10.5/sql/sql_parse.cc:1371
 
#36 0x00005559caec1453 in do_handle_one_connection (connect=0x5559ce9fa248, put_in_cache=true) at /home/elenst/src/10.5/sql/sql_connect.cc:1410
 
#37 0x00005559caec1197 in handle_one_connection (arg=0x5559ce9fa248) at /home/elenst/src/10.5/sql/sql_connect.cc:1312
 
#38 0x00005559cb411846 in pfs_spawn_thread (arg=0x5559ce8f49f8) at /home/elenst/src/10.5/storage/perfschema/pfs.cc:2201
 
#39 0x00007fa226b49ea5 in start_thread () from /lib64/libpthread.so.0
 
#40 0x00007fa224cff8dd in clone () from /lib64/libc.so.6

all threads for the above: threads_full_10_5_debug

Couldn't reproduce with rr or with debug trace.

A coredump (from a different occasion) is available.
Generated at Thu Feb 08 09:37:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.