Assertion `!recv_sys->mlog_checkpoint_lsn || *space == TRX_SYS_SPACE || srv_is_undo_tablespace(*space) || it != recv_spaces.end()' failed in recv_parse_log_rec upon prepare from a full backup
The first dataset is from the simpler full backup scenario, but it uses encryption, which is a bit of a complication. Check and update encryption options (paths) as necessary.
The second dataset is from the incremental backup scenario, even though it fails on the first prepare, performed on the full backup, before applying any incremental backups. It doesn't use encryption.
Notes on the origin of the report
Please note it's not necessarily reproducible the same way.
Backup data dirs and logs can be found here:
<wait till I upload them>
The first dataset is from the simpler full backup scenario, but it uses encryption, which is a bit of a complication. Check and update encryption options (paths) as necessary.
The second dataset is from the incremental backup scenario, even though it fails on the first prepare, performed on the full backup, before applying any incremental backups. It doesn't use encryption.
----
{panel:title=Notes on the origin of the report|bgColor=#EEE}
Please note it's not necessarily reproducible the same way.
The first dataset is from the simpler full backup scenario, but it uses encryption, which is a bit of a complication. Check and update encryption options (paths) as necessary.
The second dataset is from the incremental backup scenario, even though it fails on the first prepare, performed on the full backup, before applying any incremental backups. It doesn't use encryption.
----
{panel:title=Notes on the origin of the report|bgColor=#EEE}
Please note it's not necessarily reproducible the same way.
Basically assert was added to ensure that MLOG_FILE_NAME records was processed for the tablespace before parsing FSP_SIZE redo log records.
If there are multiple MLOG_CHECKPOINT records in the range between the latest checkpoint and the MLOG_CHECKPOINT of that latest checkpoint.
First scan only scans the last checkpoint MLOG_FILE_NAME records. It leaves out remaining MLOG_FILE_NAME records. It caused by adding
the end_lsn in checkpoint header. ( MDEV-12103). Basically we need to revert MDEV-12103 to ensure
all MLOG_FILE_NAME records are processed.
Even normal recovery could affect by the assert if we have multiple checkpoint happened between latest checkpoint and MLOG_CHECKPOINT of that
latest checkpoint.
Thirunarayanan Balathandayuthapani
added a comment - Basically assert was added to ensure that MLOG_FILE_NAME records was processed for the tablespace before parsing FSP_SIZE redo log records.
If there are multiple MLOG_CHECKPOINT records in the range between the latest checkpoint and the MLOG_CHECKPOINT of that latest checkpoint.
First scan only scans the last checkpoint MLOG_FILE_NAME records. It leaves out remaining MLOG_FILE_NAME records. It caused by adding
the end_lsn in checkpoint header. ( MDEV-12103 ). Basically we need to revert MDEV-12103 to ensure
all MLOG_FILE_NAME records are processed.
Even normal recovery could affect by the assert if we have multiple checkpoint happened between latest checkpoint and MLOG_CHECKPOINT of that
latest checkpoint.
innobase_init: ib_log: checkpoint 6 at 1707251 written
innobase_init: ib_log: MLOG_CHECKPOINT(1707251) written at 1709762
For this test case, assert was failing. Because we need to set FSP_SIZE only during apply of multiple mini-transaction not during parsing of
multiple mtr records.
marko approved the patch. So pushed the patch along with mdev-18194 fix to test it.
Thirunarayanan Balathandayuthapani
added a comment - Somehow i felt the assert is too strict. So wrote a test case to confirm it.
--source include/have_innodb.inc
--source include/have_debug.inc
CREATE TABLE t1 (f1 int not null)engine=innodb;
CREATE TABLE t2 (f1 int not null)engine=innodb;
insert into t2 values(1), (2), (3);
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
select count(*) from t2;
insert into t1 values(1), (2), (3);
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
insert into t1 select * from t1;
select count(*) from t1;
insert into t1 select * from t2;
insert into t1 values(1), (2), (3), (4), (5), (6), (7), (8), (9);
set global innodb_log_checkpoint_now = true;
--source ../include/no_checkpoint_start.inc
--echo # Below insert triggers the increase of the fsp size
insert into t1 values(1);
drop table t1;
--connection default
--let CLEANUP_IF_CHECKPOINT=DROP TABLE t1;
--source ../include/no_checkpoint_end.inc
--source include/start_mysqld.inc
--error 1146
select count(*) from t1;
drop table t2;
For the above test case, here is ib_log output:
recv_group_scan_log_recs: ib_log: scan 1708026: log rec MLOG_UNDO_INSERT len 16 page 0:334
recv_group_scan_log_recs: ib_log: Before setting recv size 1707260 space id 4
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_4BYTES len 6 page 4:0
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_1BYTE len 7 page 4:0
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_4BYTES len 6 page 4:0
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_INIT_FILE_PAGE2 len 3 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_4BYTES len 6 page 4:2
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_COMP_PAGE_CREATE len 3 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_2BYTES len 6 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_8BYTES len 10 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_COMP_REC_INSERT len 24 page 4:3
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_4BYTES len 6 page 4:5
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_4BYTES len 6 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_4BYTES len 10 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_COMP_REC_INSERT len 44 page 4:6
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log rec MLOG_FILE_NAME len 19 page 4:0
recv_group_scan_log_recs: ib_log: scan 1708058: multi-log end total_len 157 n=15
.............
..............
..............
recv_group_scan_log_recs: ib_log: scan 1709495: multi-log end total_len 17 n=3
recv_group_scan_log_recs: ib_log: scan 1709512: log rec MLOG_UNDO_INSERT len 36 page 0:335
recv_group_scan_log_recs: ib_log: scan 1709548: log rec MLOG_REC_CLUST_DELETE_MARK len 21 page 0:307
recv_group_scan_log_recs: ib_log: scan 1709585: log rec MLOG_UNDO_INSERT len 36 page 0:335
recv_group_scan_log_recs: ib_log: scan 1709621: log rec MLOG_REC_CLUST_DELETE_MARK len 21 page 0:308
recv_group_scan_log_recs: ib_log: scan 1709642: log rec MLOG_FILE_DELETE len 19 page 4:0
.......
........
recv_group_scan_log_recs: ib_log: scan 1709753 completed
innobase_init: ib_log: checkpoint 6 at 1707251 written
innobase_init: ib_log: MLOG_CHECKPOINT(1707251) written at 1709762
For this test case, assert was failing. Because we need to set FSP_SIZE only during apply of multiple mini-transaction not during parsing of
multiple mtr records.
The below patch solves the issue:
diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc
index 01801dc..9108760 100644
--- a/storage/innobase/log/log0recv.cc
+++ b/storage/innobase/log/log0recv.cc
@@ -2403,7 +2403,8 @@ recv_parse_log_rec(
}
if (*page_no == 0 && *type == MLOG_4BYTES
- && mach_read_from_2(old_ptr) == FSP_HEADER_OFFSET + FSP_SIZE) {
+ && mach_read_from_2(old_ptr) == FSP_HEADER_OFFSET + FSP_SIZE
+ && apply) {
old_ptr += 2;
ulint size = mach_parse_compressed(&old_ptr, end_ptr);
marko approved the patch. So pushed the patch along with mdev-18194 fix to test it.
Basically assert was added to ensure that MLOG_FILE_NAME records was processed for the tablespace before parsing FSP_SIZE redo log records.
If there are multiple MLOG_CHECKPOINT records in the range between the latest checkpoint and the MLOG_CHECKPOINT of that latest checkpoint.
First scan only scans the last checkpoint MLOG_FILE_NAME records. It leaves out remaining MLOG_FILE_NAME records. It caused by adding
the end_lsn in checkpoint header. ( MDEV-12103). Basically we need to revert
MDEV-12103to ensureall MLOG_FILE_NAME records are processed.
Even normal recovery could affect by the assert if we have multiple checkpoint happened between latest checkpoint and MLOG_CHECKPOINT of that
latest checkpoint.