[MDEV-25657] Atomic DDL: InnoDB: Cannot apply log, double free or corruption (fasttop) Created: 2021-05-11  Updated: 2021-05-12  Resolved: 2021-05-12

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: N/A
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-24626 Remove synchronous write of page0 and... Closed
relates to MDEV-17567 Atomic DDL Closed

 Description   

bb-10.6-monty-innodb f179fdefd1

 
2021-05-11 18:19:16 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=544370707,568276696
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/tt14.ibd' with space ID 100. Another data file called ./test/tt9.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p0.ibd' with space ID 105. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p0.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p1.ibd' with space ID 106. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p1.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/tt14.ibd' with space ID 100. Another data file called ./test/tt9.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p0.ibd' with space ID 105. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p0.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p1.ibd' with space ID 106. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p1.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/tt14.ibd' with space ID 100. Another data file called ./test/tt9.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p0.ibd' with space ID 105. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p0.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p1.ibd' with space ID 106. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p1.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-afc9-23#P#p0.ibd' with space ID 105. Another data file called ./test/table1000_innodb_varchar_378_not_null_key_pk_parts_2#P#p0.ibd exists with the same space ID.
 
2021-05-11 18:19:17 0 [Note] InnoDB: Starting a batch to recover 4665 pages from redo log.
 
2021-05-11 18:19:18 0 [ERROR] InnoDB: Cannot apply log to [page id: space=110, page number=1] of corrupted file './test/t15.ibd'
 
double free or corruption (fasttop)
 
 
 
#1  0x00001e360fcdc921 in __GI_abort () at abort.c:79
 
#2  0x00001e360fd25967 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x1e360fe52b0d "%s\n") at ../sysdeps/posix/libc_fatal.c:181
 
#3  0x00001e360fd2c9da in malloc_printerr (str=str@entry=0x1e360fe547d0 "double free or corruption (fasttop)") at malloc.c:5342
 
#4  0x00001e360fd340f4 in _int_free (have_lock=0, p=0x560ad9a5da90, av=0x1e3610087c40 <main_arena>) at malloc.c:4260
 
#5  __GI___libc_free (mem=0x560ad9a5daa0) at malloc.c:3134
 
#6  0x0000560ad6011a60 in ut_allocator<std::_Rb_tree_node<std::pair<page_id_t const, page_recv_t> >, true>::deallocate (this=0x560ad6ffc9f0 <recv_sys+304>, ptr=0x560ad9a5daa0, n_elements=1)
 
    at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/include/ut0new.h:426
 
#7  0x0000560ad6010df9 in std::allocator_traits<ut_allocator<std::_Rb_tree_node<std::pair<page_id_t const, page_recv_t> >, true> >::deallocate (__a=..., __p=0x560ad9a5daa0, __n=1) at /usr/include/c++/7/bits/alloc_traits.h:328
 
#8  0x0000560ad600fcff in std::_Rb_tree<page_id_t const, std::pair<page_id_t const, page_recv_t>, std::_Select1st<std::pair<page_id_t const, page_recv_t> >, std::less<page_id_t const>, ut_allocator<std::pair<page_id_t const, page_recv_t>, true> >::_M_put_node (this=0x560ad6ffc9f0 <recv_sys+304>, __p=0x560ad9a5daa0) at /usr/include/c++/7/bits/stl_tree.h:592
 
#9  0x0000560ad600d482 in std::_Rb_tree<page_id_t const, std::pair<page_id_t const, page_recv_t>, std::_Select1st<std::pair<page_id_t const, page_recv_t> >, std::less<page_id_t const>, ut_allocator<std::pair<page_id_t const, page_recv_t>, true> >::_M_drop_node (this=0x560ad6ffc9f0 <recv_sys+304>, __p=0x560ad9a5daa0) at /usr/include/c++/7/bits/stl_tree.h:659
 
#10 0x0000560ad600e202 in std::_Rb_tree<page_id_t const, std::pair<page_id_t const, page_recv_t>, std::_Select1st<std::pair<page_id_t const, page_recv_t> >, std::less<page_id_t const>, ut_allocator<std::pair<page_id_t const, page_recv_t>, true> >::_M_erase_aux (this=0x560ad6ffc9f0 <recv_sys+304>, __position={first = {m_id = 472446402560}, second = {state = page_recv_t::RECV_BEING_PROCESSED, last_offset = 118, log = {head = 0x0, tail = 0x0}}})
 
    at /usr/include/c++/7/bits/stl_tree.h:2477
 
#11 0x0000560ad600bae8 in std::_Rb_tree<page_id_t const, std::pair<page_id_t const, page_recv_t>, std::_Select1st<std::pair<page_id_t const, page_recv_t> >, std::less<page_id_t const>, ut_allocator<std::pair<page_id_t const, page_recv_t>, true> >::erase[abi:cxx11](std::_Rb_tree_iterator<std::pair<page_id_t const, page_recv_t> >) (this=0x560ad6ffc9f0 <recv_sys+304>, __position=
 
      {first = {m_id = 472446402560}, second = {state = page_recv_t::RECV_BEING_PROCESSED, last_offset = 118, log = {head = 0x0, tail = 0x0}}}) at /usr/include/c++/7/bits/stl_tree.h:1125
 
#12 0x0000560ad6009e4f in std::map<page_id_t const, page_recv_t, std::less<page_id_t const>, ut_allocator<std::pair<page_id_t const, page_recv_t>, true> >::erase[abi:cxx11](std::_Rb_tree_iterator<std::pair<page_id_t const, page_recv_t> >) (this=0x560ad6ffc9f0 <recv_sys+304>, __position={first = {m_id = 472446402560}, second = {state = page_recv_t::RECV_BEING_PROCESSED, last_offset = 118, log = {head = 0x0, tail = 0x0}}}) at /usr/include/c++/7/bits/stl_map.h:1031
 
#13 0x0000560ad5ffb06b in recv_sys_t::apply (this=0x560ad6ffc8c0 <recv_sys>, last_batch=false) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/log/log0recv.cc:2980
 
#14 0x0000560ad5ffd00c in recv_group_scan_log_recs (checkpoint_lsn=544370707, contiguous_lsn=0x7ffcfba516d8, last_phase=true) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/log/log0recv.cc:3485
 
#15 0x0000560ad5fff138 in recv_recovery_from_checkpoint_start (flush_lsn=54297) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/log/log0recv.cc:3939
 
#16 0x0000560ad6148c9c in srv_start (create_new_db=false) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/srv/srv0start.cc:1426
 
#17 0x0000560ad5f23b71 in innodb_init (p=0x560ad9930478) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/handler/ha_innodb.cc:3824
 
#18 0x0000560ad5b7d394 in ha_initialize_handlerton (plugin=0x560ad990df90) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/sql/handler.cc:660
 
#19 0x0000560ad5844d8b in plugin_initialize (tmp_root=0x7ffcfba523a0, plugin=0x560ad990df90, argc=0x560ad71c6e88 <remaining_argc>, argv=0x560ad98c8988, options_only=false)
 
    at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/sql/sql_plugin.cc:1463
 
#20 0x0000560ad5845ac9 in plugin_init (argc=0x560ad71c6e88 <remaining_argc>, argv=0x560ad98c8988, flags=0) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/sql/sql_plugin.cc:1756
 
#21 0x0000560ad56f5c5b in init_server_components () at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/sql/mysqld.cc:5041
 
#22 0x0000560ad56f6c13 in mysqld_main (argc=31, argv=0x560ad98c8988) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/sql/mysqld.cc:5649
 
#23 0x0000560ad56ed84a in main (argc=30, argv=0x7ffcfba54708) at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/sql/main.cc:34

The test was running a mix of DDL, locking statements and XA statements in 8 threads when it was sigkilled. The above happened upon crash recovery.

The logs, data directories and rr profiles are available.

This was a one-time occurrence so far in tests on the above-mentioned revision.

 Comments   
Comment by Marko Mäkelä [ 2021-05-12 ]

A local ASAN build repeats the recovery failure but does not trigger any ASAN message:

ASAN_OPTIONS=abort_on_error=1 ../sql/mariadbd --innodb-log-file-size=96m --datadir /dev/shm/data_before_recovery

I will try to diagnose the memory corruption first, using rr replay on the non-ASAN build that reported it.

Comment by Marko Mäkelä [ 2021-05-12 ]

The first freeing occurs here:

#8  0x0000560ad60090ef in recv_sys_t::recover_low (this=0x560ad6ffc8c0 <recv_sys>, page_id=..., p=
 
      {first = {m_id = 472446402561}, second = {state = page_recv_t::RECV_WILL_NOT_READ, last_offset = 1, log = {head = 0x3b0b23f474e0, tail = 0x3b0b23f47500}}}, mtr=..., b=0x3b0b23867b30)
 
    at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/log/log0recv.cc:2862
 
#9  0x0000560ad5ff2271 in recv_sys_t::recover_deferred (this=0x560ad6ffc8c0 <recv_sys>, space_id=110, 
    name="./test/t15.ibd", free_block=@0x7ffcfba50df0: 0x3b0b23867b30)
 
    at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/log/log0recv.cc:750
 
#10 0x0000560ad5ffafef in recv_sys_t::apply (this=0x560ad6ffc8c0 <recv_sys>, last_batch=false)
 
    at /home/mdbe/atomic_ddl/bb-10.6-monty-for-rr/storage/innobase/log/log0recv.cc:2972

When I updated MDEV-24626 yesterday, I overlooked the fact that recv_sys_t::recover_low() will advance the iterator and free the records. There would also have been a heap-use-after-free at the end of recv_sys_t::recover_deferred(), for dereferencing the potentially freed iterator p.

I think that we must pass the iterator to recv_sys_t::recover_deferred(), so that recv_sys_t::apply() will avoid the double-freeing when discarding all buffered records for that tablespace.

However, the root cause of the failure needs to be addressed as well: Why did we fail to recover in the first place? As far as I can tell, the doublewrite buffer was enabled before the server was intentionally killed and the recovery failed.

Comment by Marko Mäkelä [ 2021-05-12 ]

The root cause is the same as in MDEV-25656: I did not realize that it->flags are not always valid. Hence, recv_sys_t::recover_deferred() must not insist that flags == it->second.flags hold.

Comment by Marko Mäkelä [ 2021-05-12 ]

This error was introduced by my refactoring yesterday in an MDEV-24626 development branch.

Generated at Thu Feb 08 09:39:21 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.