Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
10.8(EOL), 10.9(EOL), 10.10(EOL)
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
Issue Links
- is caused by
-
-
- Closed
-
- relates to
-
MDEV-14425 Change the InnoDB redo log format to reduce write amplification
-
- Closed
-
Activity
| Field | Original Value | New Value |
|---|---|---|
| Link |
This issue relates to |
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.
| Status | Open [ 1 ] | In Progress [ 3 ] |
| Link |
This issue is caused by |
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.
| Fix Version/s | 10.6 [ 24028 ] | |
| Fix Version/s | 10.7 [ 24805 ] | |
| Labels | corruption | corruption recovery |
| issue.field.resolutiondate | 2022-06-29 13:21:17.0 | 2022-06-29 13:21:17.776 |
| Fix Version/s | 10.6.9 [ 27507 ] | |
| Fix Version/s | 10.7.5 [ 27505 ] | |
| Fix Version/s | 10.8.4 [ 27503 ] | |
| Fix Version/s | 10.9.2 [ 27115 ] | |
| Fix Version/s | 10.10.1 [ 27913 ] | |
| Fix Version/s | 10.6 [ 24028 ] | |
| Fix Version/s | 10.7 [ 24805 ] | |
| Fix Version/s | 10.8 [ 26121 ] | |
| Fix Version/s | 10.9 [ 26905 ] | |
| Fix Version/s | 10.10 [ 27530 ] | |
| Resolution | Fixed [ 1 ] | |
| Status | In Progress [ 3 ] | Closed [ 6 ] |
| Summary | mariabackup.huge_lsn,strict_full_crc32 fails | Race condition in the recovery of CREATE TABLE or table-rebuilding DDL |
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.
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/backupThe 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=175964789139002022-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.xzmv dev/shm/10.10a/mysql-test/var/22/tmp/backup /dev/shm/backupseq 1 100|while read; do rsync -al --delete /dev/shm/backup/ /dev/shm/b_$REPLY/; doneseq 1 100|while read; do ../extra/mariabackup/mariadb-backup --prepare --target-dir=/dev/shm/b_$REPLY > "$REPLY".out 2>&1 & donemd5sum /dev/shm/b*/test/t.ibdIn the output, one of the data files got a different checksum:
b575fbcd48d33754ea928060b8f436c9 /dev/shm/b_70/test/t.ibd243768ecb5107020aff347cf859968e6 /dev/shm/b_71/test/t.ibdb575fbcd48d33754ea928060b8f436c9 /dev/shm/b_72/test/t.ibdThat 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.ibd000000 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 ff004010 00 00 10 01 00 00 00 a8 00 05 00 00 00 00 00 00004020 00 00 00 00 00 05 00 00 00 00 00 00 00 00 00 00004030 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…