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

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>