[ERROR] InnoDB: Record <number1> is above rec heap top <number2> hit during restart after crash

Workflow of the test

1. Start the server

2. One session creates and fills several tables

2. One session runs  again and again   ALTER TABLE `t8` FORCE 

3. SIGKILL the server process at some point of time with ongoing 2.

4. Attempt to restart that server which fails with

      [ERROR] InnoDB: Record <number1> is above rec heap top <number2>

Snip from the server error log

----------------------------------------------

[rr 59733 3756]2020-07-13 17:59:00 0 [Note] InnoDB: Starting a batch to recover 649 pages from redo log.

[rr 59733 6404]2020-07-13 17:59:00 0 [ERROR] InnoDB: Record 125 is above rec heap top 120

[rr 59733 6408]2020-07-13 17:59:00 0 [Note] InnoDB: Uncompressed page, stored checksum in field1 0, calculated checksums for field1: crc32 326468837, innodb 2664178674,  page type 17855 == INDEX.none 3735928559, stored checksum in field2 41467269, calculated checksums for field2: crc32 326468837, innodb 1737752431, none 3735928559,  page LSN 0 41467269, low 4 bytes of LSN at page end 638991405, page number (if stored to page already) 7, space id (if created with >= MySQL-4.1.1 and stored already) 14

 [rr 59733 6412]2020-07-13 17:59:00 0 [Note] InnoDB: Page may be an index page where index id is 43

[rr 59733 6416]2020-07-13 17:59:00 0 [ERROR] [FATAL] InnoDB: Apparent corruption of an index page [page id: space=14, page number=7] to be written to data file. We intentionally crash the server to prevent corrupt data from ending up in data files.

[rr 59733 6437]200713 17:59:00 [rr 59733 6439][ERROR] mysqld got signal 6 ;

(rr) bt

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

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

#2  0x000055c3ade1616c in ib::fatal::~fatal (this=<optimized out>, __in_chrg=<optimized out>) at storage/innobase/ut/ut0ut.cc:580

#3  0x000055c3adea15f0 in buf_dblwr_assert_on_corrupt_block (block=block@entry=0x2b9e00e53600) at storage/innobase/buf/buf0dblwr.cc:769

#4  0x000055c3adea16a0 in buf_dblwr_check_block (block=block@entry=0x2b9e00e53600) at storage/innobase/buf/buf0dblwr.cc:828

#5  0x000055c3adea21b1 in buf_dblwr_flush_buffered_writes () at storage/innobase/buf/buf0dblwr.cc:944

#6  0x000055c3adea368a in buf_dblwr_t::add_to_batch (this=0x55c3afe9a298, bpage=bpage@entry=0x2b9e00e51f80, flush=flush@entry=IORequest::FLUSH_LIST, size=<optimized out>) at storage/innobase/buf/buf0dblwr.cc:1060

#7  0x000055c3adeb5592 in buf_flush_page (bpage=bpage@entry=0x2b9e00e51f80, flush_type=flush_type@entry=IORequest::FLUSH_LIST, space=space@entry=0x55c3afecc0a8, sync=sync@entry=false) at storage/innobase/buf/buf0flu.cc:1185

#8  0x000055c3adeb6264 in buf_flush_try_neighbors (page_id=page_id@entry=..., flush=flush@entry=IORequest::FLUSH_LIST, n_flushed=n_flushed@entry=100, n_to_flush=n_to_flush@entry=18446744073709551614)

    at storage/innobase/buf/buf0flu.cc:1432

#9  0x000055c3adeb710d in buf_do_flush_list_batch (min_n=min_n@entry=18446744073709551614, lsn_limit=lsn_limit@entry=18446744073709551615) at storage/innobase/buf/buf0flu.cc:1640

#10 0x000055c3adeb755d in buf_flush_batch (lru=lru@entry=false, min_n=min_n@entry=18446744073709551614, lsn_limit=lsn_limit@entry=18446744073709551615, n=n@entry=0x7ca320410c70) at storage/innobase/buf/buf0flu.cc:1697

#11 0x000055c3adeb75cf in buf_flush_do_batch (lru=lru@entry=false, min_n=18446744073709551614, lsn_limit=18446744073709551615, n=n@entry=0x7ca320410c70) at storage/innobase/buf/buf0flu.cc:1800

#12 0x000055c3adeb79f3 in pc_flush_slot () at storage/innobase/buf/buf0flu.cc:2397

#13 0x000055c3adeb7c7e in buf_flush_page_cleaner () at storage/innobase/buf/buf0flu.cc:2559

#14 0x00006c31626036db in start_thread (arg=0x7ca320411700) at pthread_create.c:463

#15 0x000038fd5ba45a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(rr)

10.5.5 origin/10.5 272620399425a1b59f6565ff130970bca6d9b4f9 2020-07-11T14:04:53+00:00

RQG

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

origin/experimental fb64e6bde15cd4efcd466562873156ebb9f9c8b0 2020-07-10T21:35:50+02:00

Simplified YY grammar (the full grammar was innodb_compression_encryption.yy)

query:

    ALTER TABLE `t8` FORCE ;

query_init:

    ;

thread_connect:

    ;

perl rqg.pl \                        

--duration=100 \

--queries=10000000 \

--threads=1 \

--no_mask \

--seed=random \

--rpl_mode=none \

--engine=InnoDB \

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

--sqltrace \

--mysqld=--innodb-lock-wait-timeout=50 \

--mysqld=--loose-idle_readonly_transaction_timeout=0 \

--mysqld=--loose_innodb_use_native_aio=0 \

--mysqld=--connect_timeout=60 \

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

--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \

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

--mysqld=--lock-wait-timeout=86400 \

--mysqld=--log-bin \

--mysqld=--innodb_stats_persistent=off \

--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \

--mysqld=--wait_timeout=28800 \

--mysqld=--loose-idle_transaction_timeout=0 \

--mysqld=--log_bin_trust_function_creators=1 \

--mysqld=--log-output=none \

--mysqld=--net_read_timeout=30 \

--mysqld=--slave_net_timeout=60 \

--mysqld=--loose-table_lock_wait_timeout=50 \

--mysqld=--loose-idle_write_transaction_timeout=0 \

--mysqld=--net_write_timeout=60 \

--mysqld=--interactive_timeout=28800 \

--mysqld=--loose-debug_assert_on_not_freed_memory=0 \

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

--validators=None \

--grammar=<simplified grammar> \

--workdir=<local settings> \

--vardir=<local settings> \

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

--basedir1=<local settings> \

--script_debug=_nix_ \

--rr=Server \

--rr_options=--chaos