From b40a1fbc9394637b4038b7862906be19623480b9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marko=20M=C3=A4kel=C3=A4?= Date: Tue, 24 Jan 2017 10:29:29 +0200 Subject: [PATCH] MDEV-11782 WIP: Clean up the code, and add a test. LOG_CHECKPOINT_ARRAY_END, LOG_CHECKPOINT_SIZE: Remove. Change some error messages to refer to MariaDB 10.2.2 instead of MySQL 5.7.9. recv_find_max_checkpoint_0(): Do not abort when decrypting one of the checkpoint pages fails. --- .../r/innodb_encrypt_log_corruption.result | 97 +++++++++++++++++++ .../t/innodb_encrypt_log_corruption.opt | 5 + .../t/innodb_encrypt_log_corruption.test | 14 +++ .../suite/innodb/r/log_corruption.result | 17 ++-- mysql-test/suite/innodb/t/log_corruption.test | 25 ++--- storage/innobase/include/log0log.h | 12 +-- storage/innobase/log/log0log.cc | 3 - storage/innobase/log/log0recv.cc | 15 ++- 8 files changed, 149 insertions(+), 39 deletions(-) create mode 100644 mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.result create mode 100644 mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.opt create mode 100644 mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.test diff --git a/mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.result b/mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.result new file mode 100644 index 00000000000..35d73cda0ec --- /dev/null +++ b/mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.result @@ -0,0 +1,97 @@ +# redo log from before MariaDB 10.2.2/MySQL 5.7.9 +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\.2\.2\./ in mysqld.1.err +# redo log from before MariaDB 10.2.2, with corrupted log checkpoint +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\.2\.2, and we did not find a valid checkpoint/ in mysqld.1.err +FOUND /Plugin 'InnoDB' registration as a STORAGE ENGINE failed/ in mysqld.1.err +# redo log from before MariaDB 10.2.2, with corrupted log block +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\.2\.2, and it appears corrupted/ in mysqld.1.err +# redo log from "after" MariaDB 10.2.2, but with invalid header checksum +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Invalid redo log header checksum/ in mysqld.1.err +# distant future redo log format, with valid header checksum +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Unsupported redo log format. The redo log was created with malicious intentions, or perhaps\. Please follow the instructions at http://dev.mysql.com/doc/refman/5.7/en/upgrading-downgrading.html/ in mysqld.1.err +# valid header, but old-format checkpoint blocks +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: No valid checkpoint found .corrupted redo log/ in mysqld.1.err +# valid header, valid checkpoint 1, all-zero (invalid) checkpoint 2, invalid block checksum +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Invalid log block checksum. block: 2372 checkpoint no: 1 expected: 3362026715 found: 144444122/ in mysqld.1.err +FOUND /InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 1213964 and the end 1213952\./ in mysqld.1.err +# --innodb-force-recovery=6 (skip the entire redo log) +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +InnoDB YES Supports transactions, row-level locking, foreign keys and encryption for tables YES YES YES +FOUND /\[Note\] InnoDB: .* started; log sequence number 0/ in mysqld.1.err +# valid header, valid checkpoint 1, all-zero (invalid) checkpoint 2, invalid block number +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 1213964 and the end 1213952\./ in mysqld.1.err +# --innodb-force-recovery=6 (skip the entire redo log) +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +InnoDB YES Supports transactions, row-level locking, foreign keys and encryption for tables YES YES YES +# Test a corrupted MLOG_FILE_NAME record. +# valid header, valid checkpoint 1, all-zero (invalid) checkpoint 2 +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Log scan progressed past the checkpoint lsn 1213964/ in mysqld.1.err +FOUND /InnoDB: ############### CORRUPT LOG RECORD FOUND ##################/ in mysqld.1.err +FOUND /InnoDB: Log record type 55, page 151:488\. Log parsing proceeded successfully up to 1213973\. Previous log record type 56, is multi 0 Recv offset 9, prev 0/ in mysqld.1.err +FOUND /len 22. hex 38000000000012860cb7809781e80006626f67757300. asc 8 bogus / in mysqld.1.err +FOUND /InnoDB: Set innodb_force_recovery to ignore this error/ in mysqld.1.err +# Test a corrupted MLOG_FILE_NAME record. +# valid header, invalid checkpoint 1, valid checkpoint 2, invalid block +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /InnoDB: Invalid log block checksum. block: 2372 checkpoint no: 1 expected: 2454333373 found: 150151/ in mysqld.1.err +# valid header, invalid checkpoint 1, valid checkpoint 2, invalid log record +SELECT * FROM INFORMATION_SCHEMA.ENGINES +WHERE engine = 'innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS +FOUND /len 22; hex 38000000000012860cb7809781e800066269676f7400; asc 8 bigot ;/ in mysqld.1.err +# Minimal MariaDB 10.1.21 encrypted redo log +# FIXME: Upgrade from a clean encrypted redo log should actually work! +SELECT COUNT(*) `1` FROM INFORMATION_SCHEMA.ENGINES WHERE engine='innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); +1 +0 +ib_buffer_pool +ib_logfile0 +ib_logfile1 +ibdata1 diff --git a/mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.opt b/mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.opt new file mode 100644 index 00000000000..8070b5a6182 --- /dev/null +++ b/mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.opt @@ -0,0 +1,5 @@ +--innodb-encrypt-log=ON +--plugin-load-add=$FILE_KEY_MANAGEMENT_SO +--loose-file-key-management +--loose-file-key-management-filename=$MYSQL_TEST_DIR/std_data/logkey.txt +--file-key-management-encryption-algorithm=aes_cbc diff --git a/mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.test b/mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.test new file mode 100644 index 00000000000..c4cd233e4ac --- /dev/null +++ b/mysql-test/suite/encryption/t/innodb_encrypt_log_corruption.test @@ -0,0 +1,14 @@ +--let $no_cleanup=1 +--source ../../innodb/t/log_corruption.test + +--echo # FIXME: Upgrade from a clean encrypted redo log should actually work! + +SELECT COUNT(*) `1` FROM INFORMATION_SCHEMA.ENGINES WHERE engine='innodb' +AND support IN ('YES', 'DEFAULT', 'ENABLED'); + +--let $restart_parameters= +--source include/restart_mysqld.inc + +--list_files $bugdir +--remove_files_wildcard $bugdir +--rmdir $bugdir diff --git a/mysql-test/suite/innodb/r/log_corruption.result b/mysql-test/suite/innodb/r/log_corruption.result index 1397334984c..ad06398e4e2 100644 --- a/mysql-test/suite/innodb/r/log_corruption.result +++ b/mysql-test/suite/innodb/r/log_corruption.result @@ -1,24 +1,23 @@ -# redo log from before MySQL 5.7.9 +# redo log from before MariaDB 10.2.2/MySQL 5.7.9 SELECT * FROM INFORMATION_SCHEMA.ENGINES WHERE engine = 'innodb' AND support IN ('YES', 'DEFAULT', 'ENABLED'); ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS -FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MySQL 5\.7\.9\./ in mysqld.1.err -# redo log from before MySQL 5.7.9, with corrupted log checkpoint +FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\.2\.2\./ in mysqld.1.err +# redo log from before MariaDB 10.2.2, with corrupted log checkpoint SELECT * FROM INFORMATION_SCHEMA.ENGINES WHERE engine = 'innodb' AND support IN ('YES', 'DEFAULT', 'ENABLED'); ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS -FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MySQL 5\.7\.9, and we did not find a valid checkpoint/ in mysqld.1.err +FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\.2\.2, and we did not find a valid checkpoint/ in mysqld.1.err FOUND /Plugin 'InnoDB' registration as a STORAGE ENGINE failed/ in mysqld.1.err -NOT FOUND /Unknown/unsupported storage engine: InnoDB/ in mysqld.1.err -# redo log from before MySQL 5.7.9, with corrupted log block +# redo log from before MariaDB 10.2.2, with corrupted log block SELECT * FROM INFORMATION_SCHEMA.ENGINES WHERE engine = 'innodb' AND support IN ('YES', 'DEFAULT', 'ENABLED'); ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS -FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MySQL 5\.7\.9, and it appears corrupted/ in mysqld.1.err -# redo log from "after" MySQL 5.7.9, but with invalid header checksum +FOUND /InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\.2\.2, and it appears corrupted/ in mysqld.1.err +# redo log from "after" MariaDB 10.2.2, but with invalid header checksum SELECT * FROM INFORMATION_SCHEMA.ENGINES WHERE engine = 'innodb' AND support IN ('YES', 'DEFAULT', 'ENABLED'); @@ -92,7 +91,7 @@ WHERE engine = 'innodb' AND support IN ('YES', 'DEFAULT', 'ENABLED'); ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS FOUND /InnoDB: Redo log crypto: getting mysqld crypto key from key version failed err = 4294967295/ in mysqld.1.err -FOUND /InnoDB: Reading checkpoint encryption info failed/ in mysqld.1.err +FOUND /InnoDB: Decrypting checkpoint failed/ in mysqld.1.err ib_buffer_pool ib_logfile0 ib_logfile1 diff --git a/mysql-test/suite/innodb/t/log_corruption.test b/mysql-test/suite/innodb/t/log_corruption.test index f7212d36c06..0f59f64ebdf 100644 --- a/mysql-test/suite/innodb/t/log_corruption.test +++ b/mysql-test/suite/innodb/t/log_corruption.test @@ -14,7 +14,7 @@ call mtr.add_suppression("InnoDB: MLOG_FILE_NAME incorrect"); call mtr.add_suppression("InnoDB: ############### CORRUPT LOG RECORD FOUND"); call mtr.add_suppression("InnoDB: Found corrupted log"); call mtr.add_suppression("InnoDB: Redo log crypto: getting mysqld crypto key from key version failed"); -call mtr.add_suppression("InnoDB: Reading checkpoint encryption info failed"); +call mtr.add_suppression("InnoDB: Decrypting checkpoint failed"); --enable_query_log let bugdir= $MYSQLTEST_VARDIR/tmp/log_corruption; @@ -90,7 +90,7 @@ binmode OUT; print OUT chr(0) x 1048576; close OUT or die; -# Create a redo log from before MySQL 5.7.9 +# Create a redo log from before MariaDB 10.2.2/MySQL 5.7.9 die unless open OUT, ">", "$ENV{bugdir}/ib_logfile0"; binmode OUT; print OUT pack("x[9]nx[5]", 0x1286), " ", chr(0) x 492; @@ -102,30 +102,28 @@ print OUT chr(0) x 1046016; close OUT or die; EOF ---echo # redo log from before MySQL 5.7.9 +--echo # redo log from before MariaDB 10.2.2/MySQL 5.7.9 --let $restart_parameters= $dirs --source include/restart_mysqld.inc eval $check_no_innodb; --source include/shutdown_mysqld.inc -let SEARCH_PATTERN=InnoDB: Upgrade after a crash is not supported. This redo log was created before MySQL 5\\.7\\.9\\.; +let SEARCH_PATTERN=InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\\.2\\.2\\.; --source include/search_pattern_in_file.inc ---echo # redo log from before MySQL 5.7.9, with corrupted log checkpoint +--echo # redo log from before MariaDB 10.2.2, with corrupted log checkpoint --move_file $bugdir/ib_logfile0 $bugdir/ib_logfile --copy_file $bugdir/ib_logfile1 $bugdir/ib_logfile0 --source include/start_mysqld.inc eval $check_no_innodb; --source include/shutdown_mysqld.inc -let SEARCH_PATTERN=InnoDB: Upgrade after a crash is not supported. This redo log was created before MySQL 5\\.7\\.9, and we did not find a valid checkpoint; +let SEARCH_PATTERN=InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\\.2\\.2, and we did not find a valid checkpoint; --source include/search_pattern_in_file.inc let SEARCH_PATTERN=Plugin 'InnoDB' registration as a STORAGE ENGINE failed; --source include/search_pattern_in_file.inc -let SEARCH_PATTERN=Unknown/unsupported storage engine: InnoDB; ---source include/search_pattern_in_file.inc ---echo # redo log from before MySQL 5.7.9, with corrupted log block +--echo # redo log from before MariaDB 10.2.2, with corrupted log block --remove_file $bugdir/ib_logfile0 --move_file $bugdir/ib_logfile $bugdir/ib_logfile0 perl; @@ -139,10 +137,10 @@ EOF --source include/start_mysqld.inc eval $check_no_innodb; --source include/shutdown_mysqld.inc -let SEARCH_PATTERN=InnoDB: Upgrade after a crash is not supported. This redo log was created before MySQL 5\\.7\\.9, and it appears corrupted; +let SEARCH_PATTERN=InnoDB: Upgrade after a crash is not supported. This redo log was created before MariaDB 10\\.2\\.2, and it appears corrupted; --source include/search_pattern_in_file.inc ---echo # redo log from "after" MySQL 5.7.9, but with invalid header checksum +--echo # redo log from "after" MariaDB 10.2.2, but with invalid header checksum perl; die unless open OUT, "+<", "$ENV{bugdir}/ib_logfile0"; binmode OUT; @@ -337,12 +335,14 @@ print OUT pack("H*", "80000c380016000c000000015cf22e8aff355642045605c22b97f7cba9 close OUT or die; EOF +--let $restart_parameters= $dirs --innodb-force-recovery=5 --source include/start_mysqld.inc +if (!$no_cleanup) { eval $check_no_innodb; --source include/shutdown_mysqld.inc --let SEARCH_PATTERN= InnoDB: Redo log crypto: getting mysqld crypto key from key version failed err = 4294967295 --source include/search_pattern_in_file.inc ---let SEARCH_PATTERN= InnoDB: Reading checkpoint encryption info failed +--let SEARCH_PATTERN= InnoDB: Decrypting checkpoint failed --source include/search_pattern_in_file.inc --list_files $bugdir @@ -350,3 +350,4 @@ eval $check_no_innodb; --rmdir $bugdir --let $restart_parameters= --source include/start_mysqld.inc +} diff --git a/storage/innobase/include/log0log.h b/storage/innobase/include/log0log.h index 87d22946106..9ba7ca48edc 100644 --- a/storage/innobase/include/log0log.h +++ b/storage/innobase/include/log0log.h @@ -539,18 +539,16 @@ or the MySQL version that created the redo log file. */ Stored in LOG_HEADER_FORMAT. */ #define LOG_HEADER_FORMAT_CURRENT 1 -// JAN: TODO: Shoud 32 here be LOG_HEADER_CREATOR_END ? -// Problem: Log format 5.6 == 5.7 ? -#define LOG_CHECKPOINT_ARRAY_END (32 + 32 * 8) -#define LOG_CRYPT_VER (20 + LOG_CHECKPOINT_ARRAY_END) +/* @} */ + +/** MariaDB Server 10.1 encrypted redo log offsets */ +/* @{ */ +#define LOG_CRYPT_VER (20 + 32 * 9) #define LOG_CRYPT_MAX_ENTRIES (5) #define LOG_CRYPT_ENTRY_SIZE (4 + 4 + 2 * MY_AES_BLOCK_SIZE) #define LOG_CRYPT_SIZE (1 + 1 + \ (LOG_CRYPT_MAX_ENTRIES * \ LOG_CRYPT_ENTRY_SIZE)) - -#define LOG_CHECKPOINT_SIZE (20 + LOG_CHECKPOINT_ARRAY_END + \ - LOG_CRYPT_SIZE) /* @} */ #define LOG_CHECKPOINT_1 OS_FILE_LOG_BLOCK_SIZE diff --git a/storage/innobase/log/log0log.cc b/storage/innobase/log/log0log.cc index 2a905615ac1..1fe87f1250e 100644 --- a/storage/innobase/log/log0log.cc +++ b/storage/innobase/log/log0log.cc @@ -1612,9 +1612,6 @@ log_group_checkpoint( ut_ad(!srv_read_only_mode); ut_ad(log_mutex_own()); -#if LOG_CHECKPOINT_SIZE > OS_FILE_LOG_BLOCK_SIZE -# error "LOG_CHECKPOINT_SIZE > OS_FILE_LOG_BLOCK_SIZE" -#endif DBUG_PRINT("ib_log", ("checkpoint " UINT64PF " at " LSN_PF " written to group " ULINTPF, diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc index bc8b8ffd1dd..f861ff8fd10 100644 --- a/storage/innobase/log/log0recv.cc +++ b/storage/innobase/log/log0recv.cc @@ -796,9 +796,8 @@ recv_find_max_checkpoint_0( ut_fold_binary(buf + LOG_CHECKPOINT_LSN, CHECKSUM_2 - LOG_CHECKPOINT_LSN)) != mach_read_from_4(buf + CHECKSUM_2)) { - DBUG_PRINT("ib_log", - ("invalid pre-5.7.9 checkpoint " ULINTPF, - field)); + DBUG_LOG("ib_log", + "invalid pre-10.2.2 checkpoint " << field); continue; } @@ -813,8 +812,8 @@ recv_find_max_checkpoint_0( buf + LOG_CHECKPOINT_NO); if (!log_crypt_read_checkpoint_buf(buf)) { - ib::error() << "Reading checkpoint encryption info failed."; - return DB_ERROR; + ib::warn() << "Decrypting checkpoint failed"; + continue; } DBUG_PRINT("ib_log", @@ -834,14 +833,14 @@ recv_find_max_checkpoint_0( } ib::error() << "Upgrade after a crash is not supported." - " This redo log was created before MySQL 5.7.9," + " This redo log was created before MariaDB 10.2.2," " and we did not find a valid checkpoint." " Please follow the instructions at" " " REFMAN "upgrading.html"; return(DB_ERROR); } -/** Determine if a pre-5.7.9 redo log is clean. +/** Determine if a pre-MySQL 5.7.9/MariaDB 10.2.2 redo log is clean. @param[in] lsn checkpoint LSN @return error code @retval DB_SUCCESS if the redo log is clean @@ -861,7 +860,7 @@ recv_log_format_0_recover(lsn_t lsn) static const char* NO_UPGRADE_RECOVERY_MSG = "Upgrade after a crash is not supported." - " This redo log was created before MySQL 5.7.9"; + " This redo log was created before MariaDB 10.2.2"; static const char* NO_UPGRADE_RTFM_MSG = ". Please follow the instructions at " REFMAN "upgrading.html";