Debarun Banerjee added a comment - 2024-01-30 11:03 - edited 10.11: Could reproduce all the symptoms. The intermittent behaviour is caused by the page flush and intermittent checkpoint. 1. [ERROR] InnoDB: Missing FILE_CHECKPOINT(72379) at 1561912 2. [ERROR] InnoDB: Log scan aborted at LSN 1561912 We set recv_sys.set_corrupt_fs(); when not able to load the tablespace due to missing encryption key. When it happens while trying to search for the checkpoint we ignore the corrupt fs and do set_corrupt_log This is inaccurate and could be corrected by checking for corrupt fs error in callers. 3. -FOUND 1 /[ERROR] InnoDB: Encryption key is not found for .*test.t1.ibd/ in mysqld.1.err +NOT FOUND /[ERROR] InnoDB: Encryption key is not found for .*test.t1.ibd/ in mysqld.1.err Based on the flush and checkpoint we could return error for any one of t1-t5 encrypted table The test needs to be corrected. All 3 cases can be repeated by forcing intermediate flush and checkpoint. diff --git a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test index 550979680c5..646aede1947 100644 --- a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test +++ b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test @@ -32,6 +32,9 @@ while ($i) insert into t1(c,b) values (repeat( 'secret1' ,20), repeat( 'secret2' ,6000)); dec $i; } + +SET GLOBAL innodb_buf_flush_list_now = 1; +SET GLOBAL innodb_log_checkpoint_now = 1; --enable_query_log insert into t2 select * from t1; Fix (10.11): diff --git a/mysql-test/suite/encryption/r/innodb-redo-nokeys.result b/mysql-test/suite/encryption/r/innodb-redo-nokeys.result index b7d6eb50e70..ea75e4a873e 100644 --- a/mysql-test/suite/encryption/r/innodb-redo-nokeys.result +++ b/mysql-test/suite/encryption/r/innodb-redo-nokeys.result @@ -2,15 +2,10 @@ call mtr.add_suppression( "mariadbd.*: File " ); call mtr.add_suppression( "Plugin 'file_key_management' " ); call mtr.add_suppression( "InnoDB: Recovery cannot access file" ); call mtr.add_suppression( "InnoDB: Plugin initialization aborted" ); -call mtr.add_suppression( "Plugin 'InnoDB' init function returned error\\." ); call mtr.add_suppression( "Plugin 'InnoDB' registration as a STORAGE ENGINE failed." ); call mtr.add_suppression( "InnoDB: (Unable to apply log to|Discarding log for) corrupted page " ); call mtr.add_suppression( "InnoDB: Cannot apply log to \\[page id: space=[1-9][0-9]*, page number=0\\] of corrupted file '.*test.t[1-5]\\.ibd'" ); call mtr.add_suppression( "InnoDB: Failed to read page .* from file '.*'" ); -call mtr.add_suppression( "InnoDB: OPT_PAGE_CHECKSUM mismatch" ); -call mtr.add_suppression( "InnoDB: Missing FILE_CHECKPOINT" ); -call mtr.add_suppression( "InnoDB: Log scan aborted at LSN" ); -call mtr.add_suppression( "InnoDB: Set innodb_force_recovery=1 to ignore corruption" ); call mtr.add_suppression( "InnoDB: Encryption key is not found for" ); # restart: --file-key-management-filename=MYSQL_TEST_DIR/std_data/keys2.txt SET GLOBAL innodb_file_per_table = ON; @@ -42,6 +37,6 @@ SELECT * FROM INFORMATION_SCHEMA.ENGINES WHERE engine = 'innodb' AND support IN ( 'YES' , 'DEFAULT' , 'ENABLED' ); ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS -FOUND 1 /\[ERROR\] InnoDB: Encryption key is not found for .*test.t1.ibd/ in mysqld.1.err +FOUND 1 /\[ERROR\] InnoDB: Encryption key is not found for .*test.t[1-5].ibd/ in mysqld.1.err # restart: --file-key-management-filename=MYSQL_TEST_DIR/std_data/keys2.txt drop table t1,t2,t3,t4,t5; diff --git a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test index 52c12761f69..550979680c5 100644 --- a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test +++ b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test @@ -7,15 +7,10 @@ call mtr.add_suppression( "mariadbd.*: File " ); call mtr.add_suppression( "Plugin 'file_key_management' " ); call mtr.add_suppression( "InnoDB: Recovery cannot access file" ); call mtr.add_suppression( "InnoDB: Plugin initialization aborted" ); -call mtr.add_suppression( "Plugin 'InnoDB' init function returned error\\." ); call mtr.add_suppression( "Plugin 'InnoDB' registration as a STORAGE ENGINE failed." ); call mtr.add_suppression( "InnoDB: (Unable to apply log to|Discarding log for) corrupted page " ); call mtr.add_suppression( "InnoDB: Cannot apply log to \\[page id: space=[1-9][0-9]*, page number=0\\] of corrupted file '.*test.t[1-5]\\.ibd'" ); call mtr.add_suppression( "InnoDB: Failed to read page .* from file '.*'" ); -call mtr.add_suppression( "InnoDB: OPT_PAGE_CHECKSUM mismatch" ); -call mtr.add_suppression( "InnoDB: Missing FILE_CHECKPOINT" ); -call mtr.add_suppression( "InnoDB: Log scan aborted at LSN" ); -call mtr.add_suppression( "InnoDB: Set innodb_force_recovery=1 to ignore corruption" ); call mtr.add_suppression( "InnoDB: Encryption key is not found for" ); -- let $restart_parameters=--file-key-management-filename=$MYSQL_TEST_DIR/std_data/keys2.txt @@ -77,7 +72,7 @@ WHERE engine = 'innodb' AND support IN ( 'YES' , 'DEFAULT' , 'ENABLED' ); let SEARCH_FILE = $MYSQLTEST_VARDIR/ log /mysqld.1.err; -let SEARCH_PATTERN = \[ERROR\] InnoDB: Encryption key is not found for .*test.t1.ibd; +let SEARCH_PATTERN = \[ERROR\] InnoDB: Encryption key is not found for .*test.t[1-5].ibd; --source include/search_pattern_in_file.inc # diff --git a/storage/innobase/ log /log0recv.cc b/storage/innobase/ log /log0recv.cc index e72f842f9a9..21917800c66 100644 --- a/storage/innobase/ log /log0recv.cc +++ b/storage/innobase/ log /log0recv.cc @@ -4122,7 +4122,7 @@ static bool recv_scan_log( bool last_phase) ut_ad(!end || end == recv_sys.lsn); mysql_mutex_unlock(&recv_sys.mutex); - if (!end) + if (!recv_sys.is_corrupt_fs() && !end) { recv_sys.set_corrupt_log(); sql_print_error( "InnoDB: Missing FILE_CHECKPOINT(" LSN_PF @@ -4602,6 +4602,9 @@ dberr_t recv_recovery_from_checkpoint_start() LSN_PF, recv_sys.lsn); goto err_exit; } + if (recv_sys.is_corrupt_fs()) { + goto err_exit; + } ut_ad(recv_sys.file_checkpoint); if ( rewind ) { recv_sys.lsn = log_sys.next_checkpoint_lsn; @@ -4640,9 +4643,9 @@ dberr_t recv_recovery_from_checkpoint_start() do { rescan = recv_scan_log( false ); - ut_ad(!recv_sys.is_corrupt_fs()); - if (recv_sys.is_corrupt_log()) { + if (recv_sys.is_corrupt_log() || + recv_sys.is_corrupt_fs()) { goto err_exit; }

Debarun Banerjee added a comment - 2024-01-30 13:05 10.6: Two issues from 10.11 are relevant. The reason is same. 1. [ERROR] InnoDB: Missing FILE_CHECKPOINT(72379) at 1561912 2. -FOUND 1 / [ERROR] InnoDB: Encryption key is not found for .*test.t1.ibd/ in mysqld.1.err +NOT FOUND / [ERROR] InnoDB: Encryption key is not found for .*test.t1.ibd/ in mysqld.1.err Can be repeated with following change in test in debug mode. diff --git a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test index 366298026a2..cc3077b2040 100644 --- a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test +++ b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test @@ -28,6 +28,7 @@ create table t4(a int not null primary key auto_increment, c char (200), b blob, begin; --disable_query_log +SET GLOBAL innodb_buf_flush_list_now = 1; --let $i = 20 begin; while ($i) @@ -41,6 +42,7 @@ insert into t2 select * from t1; insert into t3 select * from t1; insert into t4 select * from t1; commit; +sleep 2; --source ../../suite/innodb/include/no_checkpoint_start.inc # Fix 10.6 diff --git a/mysql-test/suite/encryption/r/innodb-redo-nokeys.result b/mysql-test/suite/encryption/r/innodb-redo-nokeys.result index ce24c7c7033..9eaf8fb9430 100644 --- a/mysql-test/suite/encryption/r/innodb-redo-nokeys.result +++ b/mysql-test/suite/encryption/r/innodb-redo-nokeys.result @@ -40,6 +40,6 @@ SELECT * FROM INFORMATION_SCHEMA.ENGINES WHERE engine = 'innodb' AND support IN ( 'YES' , 'DEFAULT' , 'ENABLED' ); ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS -FOUND 1 /\[ERROR\] InnoDB: Encryption key is not found for .*test.t1.ibd/ in mysqld.1.err +FOUND 1 /\[ERROR\] InnoDB: Encryption key is not found for .*test.t[1-5].ibd/ in mysqld.1.err # restart: --file-key-management-filename=MYSQL_TEST_DIR/std_data/keys2.txt drop table t1,t2,t3,t4,t5; diff --git a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test index 7323a9148c3..366298026a2 100644 --- a/mysql-test/suite/encryption/t/innodb-redo-nokeys.test +++ b/mysql-test/suite/encryption/t/innodb-redo-nokeys.test @@ -75,7 +75,7 @@ WHERE engine = 'innodb' AND support IN ( 'YES' , 'DEFAULT' , 'ENABLED' ); let SEARCH_FILE = $MYSQLTEST_VARDIR/ log /mysqld.1.err; -let SEARCH_PATTERN = \[ERROR\] InnoDB: Encryption key is not found for .*test.t1.ibd; +let SEARCH_PATTERN = \[ERROR\] InnoDB: Encryption key is not found for .*test.t[1-5].ibd; --source include/search_pattern_in_file.inc # diff --git a/storage/innobase/ log /log0recv.cc b/storage/innobase/ log /log0recv.cc index 1d26b7a195e..502e01e1adb 100644 --- a/storage/innobase/ log /log0recv.cc +++ b/storage/innobase/ log /log0recv.cc @@ -4531,6 +4531,15 @@ recv_recovery_from_checkpoint_start(lsn_t flush_lsn) return (DB_ERROR); } + /* If we fail to open a tablespace while looking for FILE_CHECKPOINT, we + set the corruption flag. Specifically, if encryption key is missing, we + would not be able to open an encrypted tablespace and the flag could be + set. */ + if (recv_sys.is_corrupt_fs()) { + mysql_mutex_unlock(&log_sys.mutex); + return DB_ERROR; + } + if (recv_sys.mlog_checkpoint_lsn == 0) { lsn_t scan_lsn = log_sys. log .scanned_lsn; if (!srv_read_only_mode && scan_lsn != checkpoint_lsn) {

Debarun Banerjee added a comment - 2024-01-30 13:09 Only one issue is relevant for 10.5. The reason is same. 1. [ERROR] InnoDB: Missing FILE_CHECKPOINT(72379) at 1561912 Can be repeated with same debug change as 10.6 in the test. Fix 10.5 diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc index ffe35e9dbc7..620e9c9209d 100644 --- a/storage/innobase/log/log0recv.cc +++ b/storage/innobase/log/log0recv.cc @@ - 3538 , 6 + 3538 , 15 @@ recv_recovery_from_checkpoint_start(lsn_t flush_lsn) return (DB_ERROR); } + /* If we fail to open a tablespace while looking for FILE_CHECKPOINT, we + set the corruption flag. Specifically, if encryption key is missing, we + would not be able to open an encrypted tablespace and the flag could be + set. */ + if (recv_sys.found_corrupt_fs) { + mysql_mutex_unlock(&log_sys.mutex); + return DB_ERROR; + } + if (recv_sys.mlog_checkpoint_lsn == 0 ) { lsn_t scan_lsn = log_sys.log.scanned_lsn; if (!srv_read_only_mode && scan_lsn != checkpoint_lsn) {

Debarun Banerjee added a comment - 2024-01-30 14:33 Created 3 pull requests for 10.5, 10.6 & 10.11 as the patches vary. 10.5: https://github.com/MariaDB/server/pull/3031 10.6: https://github.com/MariaDB/server/pull/3032 10.11: https://github.com/MariaDB/server/pull/3033

Debarun Banerjee added a comment - 2024-01-30 14:35 Hi, I have created the review request with the patches as discussed. Please review.

Marko Mäkelä added a comment - 2024-02-02 14:14 Great work! Unrelated to your improvements, I noticed that the 10.6 and 10.11 versions of the test are being skipped very easily on my system, and also on buildbot. It could be useful to ensure that a log checkpoint is executed right before the no_checkpoint_start.inc . We can’t use the debug setting SET GLOBAL innodb_buf_flush_list_now = 1; to achieve that, because this test is targeting all builds.

Debarun Banerjee added a comment - 2024-02-08 05:17 The fix is pushed to 10.5 commit 5e7047067e4c99f61d398c9dbee1fd74ef0b1632 (HEAD -> 10.5, origin/10.5) Author: mariadb-DebarunBanerjee <debarun.banerjee@mariadb.com> Date: Tue Feb 6 15:50:10 2024 +0530 MDEV-33274 The test encryption.innodb-redo-nokeys often fails The merge to 10.6 and 10.11 is non-trivial. We need to use the following patches while merging. 10.6: https://github.com/MariaDB/server/pull/3032 10.11: https://github.com/MariaDB/server/pull/3033