[#MDEV-18602] InnoDB: Failing assertion: !recv_no_log_write upon --prepare --apply-log-only on the first (full) backup

10.1 5b827511
2019-02-16 14:19:31 139676350618560 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
2019-02-16 14:19:32 139676350618560 [Note] InnoDB: Starting a batch to recover 3925 pages from redo log
2019-02-16 14:19:39 7f08ef431bc0 InnoDB: Assertion failure in thread 139676350618560 in file mtr0mtr.cc line 322
InnoDB: Failing assertion: !recv_no_log_write

#4 0x00007f08ed31e3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
#5 0x000055da27e57127 in mtr_commit (mtr=0x7fffa8abe370) at /data/src/10.1/storage/xtradb/mtr/mtr0mtr.cc:322
#6 0x000055da27faed4b in dict_boot () at /data/src/10.1/storage/xtradb/dict/dict0boot.cc:454
#7 0x000055da27f2c4b6 in innobase_start_or_create_for_mysql () at /data/src/10.1/storage/xtradb/srv/srv0start.cc:2649
#8 0x000055da2768cb85 in innodb_init () at /data/src/10.1/extra/mariabackup/xtrabackup.cc:1798
#9 0x000055da27695ce5 in xtrabackup_prepare_func (argc=3, argv=0x7f08ec820648) at /data/src/10.1/extra/mariabackup/xtrabackup.cc:5979
#10 0x000055da27697ffa in main (argc=5, argv=0x7fffa8ac2cd8) at /data/src/10.1/extra/mariabackup/xtrabackup.cc:6824

To reproduce, upload and unpack the backup from here:
ftp://perro.askmonty.org/public/jira/mdev18602-backup.tar.gz
and run

bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=`pwd`/backup_before_prepare_0

It was meant to be the initial part of an incremental backup, which is why prepare is run with apply-log-only as documented; I'm not including further incremental backups because they are unimportant for reproducing.

Backup log is attached as mbackup_backup_0.log.
As far as I know, there is no DDL in the test flow at the time when the backup is taken; it does, however, include fairly big values for blobs (text fields), which seems to be essential for the problem. The general log is attached as mysql.log.gz.

The failure happens a lot in my tests on 10.1 and is reproducible easily with random tests, but converting it into a deterministic MTR test case seems not trivial, apparently it depends on timing and possibly requires some debug synchronization or injection.

I couldn't reproduce it so far on 10.2+.

Notes on the origin of the report

Reproducible easily enough with this:

github.com/MariaDB/randgen --branch elenst-jira-refs a51b46b6

perl ./runall-new.pl --basedir=/data/src/10.1-bug --vardir=/home/travis/logs/vardir --duration=300 --threads=1 --seed=1549825243 --reporters=Backtrace,ErrorLog,Deadlock --skip-gendata --gendata-advanced   --grammar=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=3 --mysqld=--lock-wait-timeout=2 --mysqld=--loose-innodb-lock-wait-timeout=1   --engine=InnoDB --scenario=MariaBackupIncremental

[MDEV-18602] InnoDB: Failing assertion: !recv_no_log_write upon --prepare --apply-log-only on the first (full) backup Created: 2019-02-16 Updated: 2021-05-11
Status:	Open
Project:	MariaDB Server
Component/s:	mariabackup, Storage Engine - InnoDB
Affects Version/s:	10.1
Fix Version/s:	10.1

[MDEV-18602] InnoDB: Failing assertion: !recv_no_log_write upon --prepare --apply-log-only on the first (full) backup Created: 2019-02-16 Updated: 2021-05-11