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

log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 34U) == block.page.id().space()' failed during CrashRecovery

Details

    Description

      origin/10.6 aaef2e1d8c843d1e40b1ce0c5199c3abb3c5da28 2021-11-18T17:47:19+02:00
      Workflow:
      1. Start the DB server and create some initial data.
      2. One session runs a DDL/DML mix.
      3. During 2. is ongoing SIGKILL the DB server.
      4. Restart attempt
      # 2021-11-18T17:44:24 [3378597] | [rr 3525669 23847]2021-11-18 17:43:54 0 [Note] InnoDB: Read redo log up to LSN=100581888
      # 2021-11-18T17:44:24 [3378597] | [rr 3525669 23851]2021-11-18 17:43:55 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-339c96-10.ibd' with space ID 48. Another data file called ./test/t8.ibd exists with the same space ID.
      # 2021-11-18T17:44:24 [3378597] | [rr 3525669 23855]2021-11-18 17:43:55 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-339c96-10.ibd' with space ID 48. Another data file called ./test/t8.ibd exists with the same space ID.
      # 2021-11-18T17:44:24 [3378597] | [rr 3525669 23859]2021-11-18 17:43:55 0 [Note] InnoDB: Starting a batch to recover 301 pages from redo log.
      # 2021-11-18T17:44:24 [3378597] | [rr 3525669 23873]2021-11-18 17:43:55 0 [ERROR] InnoDB: Space id and page no stored in the page, read in are [page id: space=4279425345, page number=2], should be [page id: space=48, page number=2]
      # 2021-11-18T17:44:24 [3378597] | [rr 3525669 23878]mysqld: /data/Server/10.6_WAT/storage/innobase/log/log0recv.cc:276: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 34U) == block.page.id().space()' failed.
       
      (rr) bt
      #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      #1  0x00007fa1a449f859 in __GI_abort () at abort.c:79
      #2  0x00007fa1a449f729 in __assert_fail_base (fmt=0x7fa1a4635588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55627d1f90c0 "mach_read_from_4(frame + 34U) == block.page.id().space()", 
          file=0x55627d1f8a00 "/data/Server/10.6_WAT/storage/innobase/log/log0recv.cc", line=276, function=<optimized out>) at assert.c:92
      #3  0x00007fa1a44b0f36 in __GI___assert_fail (assertion=0x55627d1f90c0 "mach_read_from_4(frame + 34U) == block.page.id().space()", file=0x55627d1f8a00 "/data/Server/10.6_WAT/storage/innobase/log/log0recv.cc", line=276, 
          function=0x55627d1f8de0 "log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const") at assert.c:101
      #4  0x000055627bce0c24 in log_phys_t::apply (this=0x7fa198356028, block=..., last_offset=@0x6060001b490c: 0) at /data/Server/10.6_WAT/storage/innobase/log/log0recv.cc:276
      #5  0x000055627bcc70ec in recv_recover_page (block=0x7fa1981a0aa0, mtr=..., Traceback (most recent call last):
        File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1522, in __call__
          return self.lookup[basename].invoke(val)
        File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1459, in invoke
          return self.function(self.name, value)
        File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 649, in __init__
          self.link_type = nodetype.pointer()
      AttributeError: 'NoneType' object has no attribute 'pointer'
      p=
      ..., space=0x612000022b40, init=0x0) at /data/Server/10.6_WAT/storage/innobase/log/log0recv.cc:2649
      #6  0x000055627bcc86a6 in recv_recover_page (space=0x612000022b40, bpage=0x7fa1981a0aa0) at /data/Server/10.6_WAT/storage/innobase/log/log0recv.cc:2837
      #7  0x000055627c0af55f in buf_page_t::read_complete (this=0x7fa1981a0aa0, node=...) at /data/Server/10.6_WAT/storage/innobase/buf/buf0buf.cc:3672
      #8  0x000055627c1c8a92 in fil_aio_callback (request=...) at /data/Server/10.6_WAT/storage/innobase/fil/fil0fil.cc:2926
      #9  0x000055627bd383a6 in io_callback (cb=0x7fa19874b768) at /data/Server/10.6_WAT/storage/innobase/os/os0file.cc:3604
      #10 0x000055627c2fb1b0 in tpool::task_group::execute (this=0x612000022750, t=0x7fa19874b7c0) at /data/Server/10.6_WAT/tpool/task_group.cc:55
      #11 0x000055627c2fba79 in tpool::task::execute (this=0x7fa19874b7c0) at /data/Server/10.6_WAT/tpool/task.cc:32
      #12 0x000055627c2e8227 in tpool::thread_pool_generic::worker_main (this=0x618000000880, thread_var=0x63000001fd80) at /data/Server/10.6_WAT/tpool/tpool_generic.cc:549
      #13 0x000055627c2fac11 in std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__f=
          @0x604000000968: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x55627c2e8044 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>, __t=@0x604000000960: 0x618000000880)
          at /usr/include/c++/9/bits/invoke.h:73
      #14 0x000055627c2fa9bc in std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> (__fn=
          @0x604000000968: (void (tpool::thread_pool_generic::*)(class tpool::thread_pool_generic * const, struct tpool::worker_data *)) 0x55627c2e8044 <tpool::thread_pool_generic::worker_main(tpool::worker_data*)>) at /usr/include/c++/9/bits/invoke.h:95
      #15 0x000055627c2fa84d in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul> (this=0x604000000958) at /usr/include/c++/9/thread:244
      #16 0x000055627c2fa797 in std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator() (this=0x604000000958) at /usr/include/c++/9/thread:251
      #17 0x000055627c2fa6fc in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run (this=0x604000000950) at /usr/include/c++/9/thread:195
      #18 0x00007fa1a48acd84 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
      #19 0x00007fa1a49c6609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #20 0x00007fa1a459c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      (rr) 
       
      pluto:/data/rqg/results/1637254461/TBR-1061/dev/shm/rqg/1637254461/218/1/rr
      RQG
      ===
      # git clone https://github.com/mleich1/rqg --branch experimental RQG
      #
      # GIT_SHOW: HEAD -> experimental 5d964598d1a7eb7957b1afa9b5950ef927803070 2021-10-29T15:21:01+02:00
      # rqg.pl  : Version 4.0.2 (2021-10)
      #
      # $RQG_HOME/rqg1.pl \
      # --grammar=conf/mariadb/innodb_compression_encryption.yy \
      # --gendata=conf/mariadb/innodb_compression_encryption.zz \
      # --max_gd_duration=1800 \
      # --mysqld=--innodb-encrypt-log \
      # --mysqld=--innodb-encrypt-tables \
      # --reporters=CrashRecovery1 \
      # --mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
      # --mysqld=--loose-idle_write_transaction_timeout=0 \
      # --mysqld=--loose-idle_transaction_timeout=0 \
      # --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      # --mysqld=--connect_timeout=60 \
      # --mysqld=--interactive_timeout=28800 \
      # --mysqld=--slave_net_timeout=60 \
      # --mysqld=--net_read_timeout=30 \
      # --mysqld=--net_write_timeout=60 \
      # --mysqld=--loose-table_lock_wait_timeout=50 \
      # --mysqld=--wait_timeout=28800 \
      # --mysqld=--lock-wait-timeout=86400 \
      # --mysqld=--innodb-lock-wait-timeout=50 \
      # --no-mask \
      # --queries=10000000 \
      # --seed=random \
      # --reporters=Backtrace \
      # --reporters=ErrorLog \
      # --reporters=Deadlock1 \
      # --validators=None \
      # --mysqld=--log_output=none \
      # --mysqld=--log_bin_trust_function_creators=1 \
      # --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      # --engine=InnoDB \
      # --restart_timeout=240 \
      # --mysqld=--plugin-load-add=file_key_management.so \
      # --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
      # --duration=300 \
      # --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
      # --mysqld=--loose-innodb_read_only_compressed=OFF \
      # --mysqld=--innodb_stats_persistent=off \
      # --mysqld=--innodb_adaptive_hash_index=off \
      # --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
      # --mysqld=--loose-max-statement-time=30 \
      # --threads=1 \
      # --mysqld=--innodb-use-native-aio=0 \
      # --rr=Extended \
      # --rr_options=--wait \
      # --mysqld=--innodb_page_size=4K \
      # --mysqld=--innodb-buffer-pool-size=5M \
      # --no_mask \
      # <local settings>
      
      

      Attachments

        Issue Links

          Activity

            The table test/t8.ibd has FSP_SPACE_FLAGS of 0x13, that is, innodb_page_size=4k and innodb_checksum_algorithm=full_crc32. In FSP_SPACE_FLAGS of page 2 we have the value 0x8002, which suggests that the page contents is page_compressed. The compressed data stream in that format starts at offset 26. The assertion wrongly expects to find a valid tablespace identifier at offset 34.

            For page_compressed pages, we should defer the assertion until the page frame has been decompressed.

            I would expect 10.5 to be affected by the same. 10.4 might be affected as well, because it supports innodb_checksum_algorithm=full_crc32, but does not enable it by default.

            marko Marko Mäkelä added a comment - The table test/t8.ibd has FSP_SPACE_FLAGS of 0x13 , that is, innodb_page_size=4k and innodb_checksum_algorithm=full_crc32 . In FSP_SPACE_FLAGS of page 2 we have the value 0x8002, which suggests that the page contents is page_compressed . The compressed data stream in that format starts at offset 26. The assertion wrongly expects to find a valid tablespace identifier at offset 34. For page_compressed pages, we should defer the assertion until the page frame has been decompressed. I would expect 10.5 to be affected by the same. 10.4 might be affected as well, because it supports innodb_checksum_algorithm=full_crc32 , but does not enable it by default.

            People

              thiru Thirunarayanan Balathandayuthapani
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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