Crash recovery fails with [ERROR] InnoDB: Malformed log record

Workflow of RQG test

1. Create DB server and start it

2. One session starts to run some SQL stream against this server

3. At some point of time and not related to the state (waiting for result, sending statement, ...) of  the ongoing 2. the server process gets killed (KILL and not TERM).

4. Make some copy of the data content+logs etc. of the killed server.

5. Try to restart the killed server.

5. fails with

2020-03-31 16:17:25 0 [Note] /home/mleich/10.5/bld_debug/sql/mysqld (mysqld 10.5.2-MariaDB-debug-log) starting as process 111337 ...

...

2020-03-31 16:17:25 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=174187931

2020-03-31 16:17:25 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore.

2020-03-31 16:17:25 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=173906840) to 100 bytes after the record:

<some data>

2020-03-31 16:17:27 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error

...

2020-03-31 16:17:27 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

RQG

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

origin/experimental d417497b476e263428422b4640cf63b8e9d16afe 2020-03-30T17:17:54+02:00

MariaDB

origin/10.5 718f18599a9bcf1e7c2d3f18416fca4f7124d00d 2020-03-26T16:05:25+02:00

build with debug

perl rqg.pl \ 

--duration=120 \ 

--queries=10000000 \

--threads=1 \

--no_mask \

--seed=random \

--gendata=conf/engines/many_indexes.zz \

--rpl_mode=none \

--engine=InnoDB \

--mysqld=--innodb_stats_persistent=off \

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

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

--mysqld=--slave_net_timeout=60 \

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

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

--mysqld=--net_write_timeout=60 \

--mysqld=--connect_timeout=60 \

--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \

--mysqld=--log_bin_trust_function_creators=1 \ 

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

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

--mysqld=--interactive_timeout=28800 \

--mysqld=--innodb_page_size=32K \

--mysqld=--wait_timeout=28800 \

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

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

--mysqld=--loose_innodb_use_native_aio=1 \

--mysqld=--log-bin \

--mysqld=--net_read_timeout=30 \

--reporters=CrashRecovery1,Deadlock1,ErrorLog,None,ServerDead \

--validators=None \

--grammar=c00000.yy \

--workdir=<local settings> \

--vardir=<local settings> \

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

--basedir1=<path to MariaDB binaries> \

--script_debug=_nix

There might be several replay attempts required.