Assertion `mach_read_from_4(frame + 4U) == block.page.id().page_no()' failed in log_phys_t::apply

origin/10.6 92abdcca5a5324f0727112ab2417d10c7a8d5094 2021-01-07T09:08:09+02:00

Workflow:

1. Start the server

2. Run a DDL/DML mix by 9 sessions

3. During 2. is ongoing kill the server

4. The attempt to restart the server fails with

mysqld:storage/innobase/log/log0recv.cc:274: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 4U) == block.page.id().page_no()' failed.

(rr) bt

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50

#1  0x00007d171d43c859 in __GI_abort () at abort.c:79

#2  0x00007d171d43c729 in __assert_fail_base (fmt=0x7d171d5d2588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564bea837fc0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()", 

    file=0x564bea837960 "/Server/10.6E/storage/innobase/log/log0recv.cc", line=274, function=<optimized out>) at assert.c:92

#3  0x00007d171d44df36 in __GI___assert_fail (assertion=0x564bea837fc0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()", file=0x564bea837960 "/Server/10.6E/storage/innobase/log/log0recv.cc", line=274, 

    function=0x564bea837d40 "log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const") at assert.c:101

#4  0x0000564be906714e in log_phys_t::apply (this=0x6400003b2740, block=..., last_offset=@0x608001af92e4: 0) at /Server/10.6E/storage/innobase/log/log0recv.cc:274

#5  0x0000564be905473c in recv_recover_page (block=0x6400000e8360, 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=0x613000000c98, init=0x6070000117f0) at /Server/10.6E/storage/innobase/log/log0recv.cc:2316

#6  0x0000564be906f5c6 in recv_sys_t::recover_low (this=0x564bebab2da0 <recv_sys>, page_id=..., 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=

..., mtr=..., b=0x6400000e8360) at /Server/10.6E/storage/innobase/log/log0recv.cc:2590

#7  0x0000564be905753b in recv_sys_t::apply (this=0x564bebab2da0 <recv_sys>, last_batch=true) at /Server/10.6E/storage/innobase/log/log0recv.cc:2705

#8  0x0000564be92efde0 in srv_start (create_new_db=false) at /Server/10.6E/storage/innobase/srv/srv0start.cc:1470

#9  0x0000564be8e6c164 in innodb_init (p=0x615000002898) at /Server/10.6E/storage/innobase/handler/ha_innodb.cc:3689

#10 0x0000564be8350be1 in ha_initialize_handlerton (plugin=0x621000033010) at /Server/10.6E/sql/handler.cc:645

#11 0x0000564be7b895b4 in plugin_initialize (tmp_root=0x7ffe97cc90a0, plugin=0x621000033010, argc=0x564bebff7a00 <remaining_argc>, argv=0x615000000e08, options_only=false) at /Server/10.6E/sql/sql_plugin.cc:1459

#12 0x0000564be7b8b542 in plugin_init (argc=0x564bebff7a00 <remaining_argc>, argv=0x615000000e08, flags=0) at /Server/10.6E/sql/sql_plugin.cc:1751

#13 0x0000564be784466b in init_server_components () at /Server/10.6E/sql/mysqld.cc:4950

#14 0x0000564be784665e in mysqld_main (argc=28, argv=0x615000000e08) at /Server/10.6E/sql/mysqld.cc:5539

#15 0x0000564be783014d in main (argc=27, argv=0x7ffe97ccb7d8) at /Server/10.6E/sql/main.cc:25

(rr)

pluto:/data/Results/1610366087/CR-20/dev/shm/vardir/1610366087/50/1/rr

_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0  # Fate of the server till SIGKILL

_RR_TRACE_DIR="." rr replay --mark-stdio                      # The failing restart

RQG

====

git clone https://github.com/mleich1/rqg --branch experimental RQG

perl rqg.pl \                   

--no-mask \

--seed=1610366105 \

--duration=300 \

--engine=InnoDB \

--queries=100000000 \

--mysqld=--loose_innodb_use_native_aio=1 \

--reporters=Backtrace,ErrorLog,Deadlock1,CrashRecovery1 \

--mysqld=--innodb_undo_tablespaces=3 \

--mysqld=--innodb_immediate_scrub_data_uncompressed=1 \

--mysqld=--innodb_file_per_table=0 \

--restart_timeout=600 \

--max_gd_duration=1200 \

--mysqld=--innodb_page_size=8K \

--mysqld=--innodb-buffer-pool-size=8M \

--mysqld=--log_output=none \

--sqltrace=MarkErrors \

--grammar=conf/mariadb/innodb_compression_encryption.yy \

--gendata=conf/mariadb/innodb_compression_encryption.zz \

--mysqld=--plugin-load-add=file_key_management.so \

--mysqld=--loose-file-key-management-filename=$RQG/conf/mariadb/encryption_keys.txt \

--threads=9 \

--duration=300 \

--no_mask \

--workdir=<local settings> \

--vardir=<local settings> \

--mtr-build-thread=<local settings> \

--basedir1=<local settings> \

--basedir2=<local settings> \

--script_debug=_nix_ \

--rr=Extended \

--rr_options=--chaos

You will need several attempts for replaying the bug once.