Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-25657

Atomic DDL: InnoDB: Cannot apply log, double free or corruption (fasttop)

Details

    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.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-24626 Remove synchronous write of page0 and flushing file during file creation

          • Blocker - Blocks development and/or testing work, production could not run.
          • Closed

          Task - A task that needs to be done. MDEV-17567 Atomic DDL

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            Descending order - Click to sort in ascending order
            marko Marko Mäkelä added a comment -

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

            marko Marko Mäkelä added a comment - This error was introduced by my refactoring yesterday in an MDEV-24626 development branch.
            marko Marko Mäkelä added a comment -

            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.

            marko Marko Mäkelä added a comment - 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.
            marko Marko Mäkelä added a comment -

            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.

            marko Marko Mäkelä added a comment - 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.
            marko Marko Mäkelä added a comment -

            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.

            marko Marko Mäkelä added a comment - 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.

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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