[MDEV-28977] Race condition in the recovery of CREATE TABLE or table-rebuilding DDL - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Blocker
Resolution: Fixed
Affects Version/s: 10.8(EOL), 10.9(EOL), 10.10(EOL)
Fix Version/s: 10.6.9, 10.7.5, 10.8.4, 10.9.2, 10.10.1
Component/s: Backup, Storage Engine - InnoDB
Labels:
- corruption
- recovery

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.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

targetdir.tar.xz
288 kB
2022-06-29 09:14

Issue Links

is caused by

MDEV-24626 Remove synchronous write of page0 and flushing file during file creation

Closed

relates to

MDEV-14425 Change the InnoDB redo log format to reduce write amplification

Closed

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2022-06-29 10:12

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

…

Marko Mäkelä added a comment - 2022-06-29 10:12 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 …

Marko Mäkelä added a comment - 2022-06-29 11:53

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.

Marko Mäkelä added a comment - 2022-06-29 11:53 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.

Marko Mäkelä added a comment - 2022-06-29 12:44

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~~.

Marko Mäkelä added a comment - 2022-06-29 12:44 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 .

Marko Mäkelä added a comment - 2022-06-30 10:24

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.

Marko Mäkelä added a comment - 2022-06-30 10:24 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.

People

Assignee:: Marko Mäkelä

Reporter:: Marko Mäkelä

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 2022-06-29 09:26

Updated:: 2022-06-30 10:24

Resolved:: 2022-06-29 13:21

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration