[MDEV-28977] Race condition in the recovery of CREATE TABLE or table-rebuilding DDL Created: 2022-06-29  Updated: 2022-06-30  Resolved: 2022-06-29

Status: Closed
Project: MariaDB Server
Component/s: Backup, Storage Engine - InnoDB
Affects Version/s: 10.8, 10.9, 10.10
Fix Version/s: 10.6.9, 10.7.5, 10.8.4, 10.9.2, 10.10.1

Type: Bug Priority: Blocker
Reporter: Marko Mäkelä Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: corruption, recovery

Attachments: File targetdir.tar.xz    
Issue Links:
Problem/Incident
is caused by MDEV-24626 Remove synchronous write of page0 and... Closed
Relates
relates to MDEV-14425 Change the InnoDB redo log format to ... Closed

 Description   

The test mariabackup.huge_lsn that was rewritten in MDEV-14425 often fails, mostly on the amd64-windows builder, but occasionally also on Linux. I was able to reproduce the failure on a local ASAN build with the following simplification (disabling encryption for easier analysis):

diff --git a/mysql-test/suite/mariabackup/huge_lsn.opt b/mysql-test/suite/mariabackup/huge_lsn.opt
 
deleted file mode 100644
 
index c65b76fb7d2..00000000000
 
--- a/mysql-test/suite/mariabackup/huge_lsn.opt
 
+++ /dev/null
 
@@ -1,10 +0,0 @@
 
---innodb-encrypt-log=ON
 
---innodb-tablespaces-encryption
 
---innodb-encrypt-tables=ON
 
---innodb-encryption-rotate-key-age=1
 
---innodb-encryption-threads=4
 
---plugin-load-add=$FILE_KEY_MANAGEMENT_SO
 
---loose-file-key-management
 
---loose-file-key-management-filekey=FILE:$MTR_SUITE_DIR/filekeys-data.key
 
---loose-file-key-management-filename=$MTR_SUITE_DIR/filekeys-data.enc
 
---loose-file-key-management-encryption-algorithm=aes_cbc
 
diff --git a/mysql-test/suite/mariabackup/huge_lsn.result b/mysql-test/suite/mariabackup/huge_lsn.result
 
index 503d13fcac4..bc8c9b7a1ab 100644
 
--- a/mysql-test/suite/mariabackup/huge_lsn.result
 
+++ b/mysql-test/suite/mariabackup/huge_lsn.result
 
@@ -1,9 +1,9 @@
 
 #
 
 # MDEV-13416 mariabackup fails with EFAULT "Bad Address"
 
 #
 
-# restart: --innodb-log-file-size=4M --innodb-encrypt-log=0
 
+# restart: --innodb-log-file-size=4M
 
 FOUND 1 /InnoDB: log sequence number 17596481011216/ in mysqld.1.err
 
-CREATE TABLE t(i INT) ENGINE=INNODB ENCRYPTED=YES;
 
+CREATE TABLE t(i INT) ENGINE=INNODB;
 
 INSERT INTO t VALUES(1);
 
 # xtrabackup backup
 
 SET GLOBAL innodb_flush_log_at_trx_commit=1;
 
diff --git a/mysql-test/suite/mariabackup/huge_lsn.test b/mysql-test/suite/mariabackup/huge_lsn.test
 
index 8850e9d8954..84702bcfdef 100644
 
--- a/mysql-test/suite/mariabackup/huge_lsn.test
 
+++ b/mysql-test/suite/mariabackup/huge_lsn.test
 
@@ -1,5 +1,4 @@
 
 --source include/not_embedded.inc
 
---source include/have_file_key_management.inc
 
 
 --echo #
 
 --echo # MDEV-13416 mariabackup fails with EFAULT "Bad Address"
 
@@ -66,14 +65,14 @@ print FILE $extra;
 
 close(FILE) or die "Unable to close $file\n";
 
 EOF
 
 --let SEARCH_PATTERN= InnoDB: log sequence number 17596481011216
 
---let $restart_parameters=--innodb-log-file-size=4M --innodb-encrypt-log=0
 
+--let $restart_parameters=--innodb-log-file-size=4M
 
 }
 
 
 --source include/start_mysqld.inc
 
 let SEARCH_FILE= $MYSQLTEST_VARDIR/log/mysqld.1.err;
 
 --source include/search_pattern_in_file.inc
 
 
-CREATE TABLE t(i INT) ENGINE=INNODB ENCRYPTED=YES;
 
+CREATE TABLE t(i INT) ENGINE=INNODB;
 
 INSERT INTO t VALUES(1);
 
 
 echo # xtrabackup backup;
 
@@ -85,6 +84,7 @@ SET GLOBAL innodb_flush_log_at_trx_commit=1;
 
 INSERT INTO t VALUES(2);
 
 echo # xtrabackup prepare;
 
 --disable_result_log
 
+exec tar cJf $MYSQLTEST_VARDIR/targetdir.tar.xz $targetdir/
 
 exec $XTRABACKUP  --prepare --target-dir=$targetdir;
 
 --let $restart_parameters=
 
 --source include/restart_and_restore.inc

The test would not fail in a non-ASAN build for me. targetdir.tar.xz is a copy of a database that was restored incorrectly. Actually, I had run the --backup command under rr record, because I was anticipating an error there. But the backed up log seems to be fine. The relevant part from the backup output (only available via rr replay) is:

10.10 63961a08a6203f4d58363a9321e4cf9c8b07a9fe

 
[00] 2022-06-29 11:13:25 Redo log (from LSN 17596478913900 to 17596481013381) was copied.
 
[00] 2022-06-29 11:13:25 completed OK!

The ib_logfile0 in targetdir.tar.xz indeed contains the artificially generated records for c/d.ibd, a/b.ibd as well as the records for creating and initializing the file test/t.ibd. The test failure output contains the following:

10.10 63961a08a6203f4d58363a9321e4cf9c8b07a9fe

 
CURRENT_TEST: mariabackup.huge_lsn
 
tar: Removing leading `/' from member names
 
/dev/shm/10.10a/extra/mariabackup/mariabackup based on MariaDB server 10.10.0-MariaDB Linux (x86_64)
 
[01] 2022-06-29 11:13:32 Copying ib_logfile0 to /dev/shm/10.10a/mysql-test/var/22/mysqld.1/data/ib_logfile0
 
[01] 2022-06-29 11:13:32         ...done
 
…
 
[01] 2022-06-29 11:13:33 Copying ./mysql/transaction_registry.ibd to /dev/shm/10.10a/mysql-test/var/22/mysqld.1/data/mysql/transaction_registry.ibd
 
[01] 2022-06-29 11:13:33         ...done
 
[01] 2022-06-29 11:13:33 Copying ib_buffer_pool to /dev/shm/10.10a/mysql-test/var/22/mysqld.1/data/ib_buffer_pool
 
[01] 2022-06-29 11:13:33         ...done
 
[00] 2022-06-29 11:13:33 completed OK!
 
mysqltest: At line 92: query 'SELECT * FROM t' failed: ER_TABLE_CORRUPT (1877): Table test/t is corrupted. Please drop the table and recreate.

There was no message about applying any log. The log was replaced with a dummy one that only represents the end LSN of the backup:

000000 50 68 79 73 00 00 00 00 00 00 10 01 00 00 06 85
 
000010 4d 61 72 69 61 44 42 20 31 30 2e 31 30 2e 30 00
 
000020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
0001f0 00 00 00 00 00 00 00 00 00 00 00 00 41 17 f5 8a
 
000200 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
002000 00 00 10 01 00 00 06 85 00 00 10 01 00 00 06 85
 
002010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
002030 00 00 00 00 00 00 00 00 00 00 00 00 d7 50 d3 b5
 
002040 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
003000 fa 00 00 00 00 10 01 00 00 06 85 01 79 77 29 c7
 
003010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
a00000

Because the first page of test/t.ibd was all-zero at the time it was backed up, the subsequent server startup (and the SELECT statement) would fail due to this:

10.10 63961a08a6203f4d58363a9321e4cf9c8b07a9fe

 
2022-06-29 11:13:33 0 [ERROR] InnoDB: Expected tablespace id 5 but found 0 in the file ./test/t.ibd
 
2022-06-29 11:13:33 0 [Note] Server socket created on IP: '127.0.0.1'.
 
2022-06-29 11:13:33 0 [Note] /dev/shm/10.10a/sql/mariadbd: ready for connections.
 
Version: '10.10.0-MariaDB-debug-log'  socket: '/dev/shm/10.10a/mysql-test/var/tmp/22/mysqld.1.sock'  port: 16420  Source distribution
 
2022-06-29 11:13:33 3 [ERROR] mariadbd: Table test/t is corrupted. Please drop the table and recreate.



 Comments   
Comment by Marko Mäkelä [ 2022-06-29 ]

The cause of this test failure seems to be a race condition in mariadb-backup --prepare. I recovered the targetdir.tar.xz from the failed run correctly with the following:

tar xJf targetdir.tar.xz -C /
 
../extra/mariabackup/mariadb-backup --prepare --target-dir=var/22/tmp/backup
 
../sql/mariadbd --innodb-log-file-size=10m --innodb-buffer-pool-size=10m --datadir $(pwd)/var/22/tmp/backup

The table was accessible. The output of --prepare ended in the following (notably, no end LSN is being displayed, but the artificially created FILE_MODIFY record for c/d.ibd that is supposed to be at the start of the log is mentioned):

10.10 63961a08a6203f4d58363a9321e4cf9c8b07a9fe

 
2022-06-29 12:39:48 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=17596478913900
 
2022-06-29 12:39:48 0 [Note] InnoDB: Tablespace 127 was not found at 'c/d.ibd', but there were no modifications either.
 
2022-06-29 12:39:48 0 [Note] InnoDB: Starting final batch to recover 13 pages from redo log.

This output is not present in the mtr failure output that I quoted in the Description. That output seems to be from the --copy-back operation, from include/restart_and_restore.inc.

I suspect that mariadb-backup --prepare in the failed run was terminating prematurely, without waiting for the asynchronous data page writes to complete. Indeed, I was able to reproduce corruption by the following:

tar xJf /dev/shm/targetdir.tar.xz
 
mv dev/shm/10.10a/mysql-test/var/22/tmp/backup /dev/shm/backup
 
seq 1 100|while read; do rsync -al --delete /dev/shm/backup/ /dev/shm/b_$REPLY/; done
 
seq 1 100|while read; do ../extra/mariabackup/mariadb-backup --prepare --target-dir=/dev/shm/b_$REPLY > "$REPLY".out 2>&1 & done
 
md5sum /dev/shm/b*/test/t.ibd

In the output, one of the data files got a different checksum:

b575fbcd48d33754ea928060b8f436c9  /dev/shm/b_70/test/t.ibd
 
243768ecb5107020aff347cf859968e6  /dev/shm/b_71/test/t.ibd
 
b575fbcd48d33754ea928060b8f436c9  /dev/shm/b_72/test/t.ibd

That file is missing a write of the first page, so an attempt to start the server on this file should have reproduced exactly the same failure:

od -Ax -t x1 /dev/shm/b_71/test/t.ibd 


000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
004000 00 00 00 00 00 00 00 01 ff ff ff ff ff ff ff ff
 
004010 00 00 10 01 00 00 00 a8 00 05 00 00 00 00 00 00
 
004020 00 00 00 00 00 05 00 00 00 00 00 00 00 00 00 00
 
004030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
*
 
007ff0 00 00 00 00 00 00 00 00 00 00 00 a8 56 a7 99 96
 
…

Comment by Marko Mäkelä [ 2022-06-29 ]

Before md5sum is executed, the background processes must complete first. The easiest way for that on my system seems to be pidwait mariadb-backup.

So far, I was not able to reproduce corruption by executing an optimized non-ASAN debug executable. But, I reproduced corruption also with simulated AIO, as well as under strace but not strace -f (which would actually show the writes, which are executed in other threads). I did not have luck with https://rr-project.org (rr record) either:

rm -fr /dev/shm/b_*/
 
seq 1 100|while read
 
do
 
(rsync -al --delete /dev/shm/backup/ /dev/shm/b_$REPLY/
 
 _RR_TRACE_DIR=/dev/shm/b_$REPLY rr record -h mariadb-backup --prepare --target-dir=/dev/shm/b_$REPLY > "$REPLY".out 2>&1) &
 
done
 
pidwait rr
 
pidwait mariadb-backup
 
md5sum /dev/shm/b*/test/t.ibd|grep -v b575fbcd48d33754ea928060b8f436c9

This command occasionally reproduces the corruption for me when I remove the rr record -h invocation. In those cases, the MD5 checksum would be 243768ecb5107020aff347cf859968e6 (as in the previous comment) and everything is fine, except the first page had not been written to.

Comment by Marko Mäkelä [ 2022-06-29 ]

It looks like between the done and the pidwait there must be some delay, to ensure that at least one process will have been started.
I reproduced a failure with the --verbose parameter. The log claims that records were applied to the page 0 in tablespace 5:

FILE_CHECKPOINT(17596478913900) read at 17596481011216
 
2022-06-29 15:05:23 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=17596478913900
 
2022-06-29 15:05:23 0 [Note] InnoDB: Tablespace 127 was not found at 'c/d.ibd', but there were no modifications either.
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=0]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=45]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=45]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=45]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=46]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=46]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=46]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=48]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=48]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=48]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Starting final batch to recover 13 pages from redo log.
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=5, page number=1]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=1]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=1]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011724: [page id: space=5, page number=1]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011216: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011216: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011234: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011234: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=8]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011322: [page id: space=0, page number=8]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011539: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011322: [page id: space=0, page number=8]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011539: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=9]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013165: [page id: space=0, page number=8]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012967: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011406: [page id: space=0, page number=9]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=10]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013165: [page id: space=0, page number=8]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012967: [page id: space=0, page number=7]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011406: [page id: space=0, page number=9]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011476: [page id: space=0, page number=10]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013165: [page id: space=0, page number=8]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011406: [page id: space=0, page number=9]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011476: [page id: space=0, page number=10]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011598: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013192: [page id: space=0, page number=10]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013192: [page id: space=0, page number=10]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011598: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013192: [page id: space=0, page number=10]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013219: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013219: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=1, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013219: [page id: space=0, page number=11]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012340: [page id: space=1, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012508: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=2]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012340: [page id: space=1, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012508: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012986: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013246: [page id: space=1, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012669: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013246: [page id: space=1, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011252: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013246: [page id: space=1, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011439: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011439: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012669: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: Applying log to page [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012816: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011557: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013095: [page id: space=0, page number=310]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011557: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012816: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013273: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013273: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013273: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013300: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013300: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012168: [page id: space=0, page number=307]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013300: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013327: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012238: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013327: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481011880: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013327: [page id: space=2, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012410: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013049: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012410: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013049: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012610: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013354: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012610: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013354: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012765: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481013354: [page id: space=5, page number=3]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012765: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=308]
 
2022-06-29 15:05:23 0 [Note] InnoDB: apply 17596481012897: [page id: space=0, page number=308]
 
[00] 2022-06-29 15:05:24 Last binlog file , position 0
 
[00] 2022-06-29 15:05:24 completed OK!

Finally, I figured out that recv_sys_t::recover_deferred() is releasing the exclusive page latch prematurely, before the tablespace has been created. I think that what happened was that an attempt to write the page was made, but the tablespace did not exist yet. Hence, the modified page was discarded. With that fixed, the recovery of this data directory no longer failed for me. This race condition (affecting page 0 initialization only) affect 10.6 already, due to MDEV-24626.

Comment by Marko Mäkelä [ 2022-06-30 ]

This race condition in recovery would cause a failure to access a table that was created shortly before a backup was completed, or the server had been killed.

Generated at Thu Feb 08 10:04:55 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.