[MDEV-19335] Removal of encrypted from buf_page_t Created: 2019-04-25  Updated: 2020-08-25  Resolved: 2019-10-09

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB
Affects Version/s: 10.3.14
Fix Version/s: 10.2.28, 10.3.19, 10.4.9

Type: Bug Priority: Major
Reporter: Hartmut Holzgraefe Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-12699 Improve crash recovery of corrupted d... Closed

 Description   

A data import (using SQLines as import tool) into encrypted tables failed with:

SHOW WARNINGS: LOAD DATA LOCAL INFILE 'filename' IGNORE INTO
TABLE db_name.table:name
Level: Warning; Code: 192; Message: Table
db_name.table_name is encrypted but encryption service or used
key_id is not available. Can't continue reading table.
Level: Warning; Code: 192; Message: Table
db_name.table_name is encrypted but encryption service or used
key_id is not available. Can't continue reading table.
Level: Error; Code: 1296; Message: Got error 192 'Table encrypted but
decryption failed. This could be because correct encryption management
plugin is not loaded, used encryption key is not available or encryption
method does not match.' from InnoDB

Simple file_key_management is used to manage encryption keys,
all tables use the same key id, and there has only been a single
key version.

Still just this one table reports encryption key errors, while other
encrypted tables using the same key id and version still work fine.

E.g. when checing tablespace encryption information for the table "table_name" triggering the error, and another table "other_table" that works fine, there are no visible differences apart from the space number and table name:

SELECT * FROM
INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION
WHERE NAME in
('db_name/table_name', 'db_name/other_table')\G
*************************** 1. row ***************************
SPACE: 3406
NAME: db_name/other_table
ENCRYPTION_SCHEME: 1
KEYSERVER_REQUESTS: 1
MIN_KEY_VERSION: 1
CURRENT_KEY_VERSION: 1
KEY_ROTATION_PAGE_NUMBER: NULL
KEY_ROTATION_MAX_PAGE_NUMBER: NULL
CURRENT_KEY_ID: 1
ROTATING_OR_FLUSHING: 0
*************************** 2. row ***************************
SPACE: 3449
NAME: db_name/table_name
ENCRYPTION_SCHEME: 1
KEYSERVER_REQUESTS: 1
MIN_KEY_VERSION: 1
CURRENT_KEY_VERSION: 1
KEY_ROTATION_PAGE_NUMBER: NULL
KEY_ROTATION_MAX_PAGE_NUMBER: NULL
CURRENT_KEY_ID: 1
ROTATING_OR_FLUSHING: 0

Error log repeatedly contains:

[ERROR] InnoDB: Failed to read file
'./db_name/table_name.ibd' at offset 1162674: Table is
encrypted but decrypt failed.
[ERROR] InnoDB: The page [page id: space=3449, page
number=1162674] in file './db_name/table_name.ibd' cannot be
decrypted.
[Note] InnoDB: However key management plugin or used key_version
1 is not found or used encryption algorithm or method does not match.
[Note] InnoDB: Marking tablespace as missing. You may drop this
table or install correct key management plugin and key file.



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2019-05-02 ]

The following mtr test case can repeat the user case scenario:

-- source include/have_innodb.inc
-- source include/have_file_key_management_plugin.inc
 
--disable_query_log
let $encrypt_tables = `SELECT @@innodb_encrypt_tables`;
let $threads = `SELECT @@innodb_encryption_threads`;
let $key_id = `SELECT @@innodb_default_encryption_key_id`;
--enable_query_log
 
SET GLOBAL innodb_encryption_threads = 4;
 
CREATE TABLE t1 (pk INT PRIMARY KEY AUTO_INCREMENT, c VARCHAR(256)) ENGINE=INNODB ENCRYPTED=YES;
 
--disable_warnings
--disable_query_log
begin;
let $i = 10;
while ($i)
{
INSERT INTO t1 values(NULL, substring(MD5(RAND()), -128));
dec $i;
}
commit;
--enable_warnings
--enable_query_log
 
let INNODB_PAGE_SIZE=`select @@innodb_page_size`;
let MYSQLD_DATADIR=`select @@datadir`;
 
eval select * into outfile "$MYSQLTEST_VARDIR/tmp/t1.outfile" from t1;
 
select count(*) from t1;
 
CREATE TABLE t2 (pk INT, c CHAR(255)) ENGINE=INNODB ENCRYPTED=YES;
 
insert into t2 values(999, "sql"), (2000, "server"), (100, "mariadb"),
                (101, "mariadb"), (102, "test1"), (103, "test2"), (104, "test3");
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
insert into t2 select * from t2;
 
 
select count(*) from t2;
 
--source include/shutdown_mysqld.inc
--echo # Corrupt the pages
 
perl;
my $ps = $ENV{INNODB_PAGE_SIZE};
 
my $file = "$ENV{MYSQLD_DATADIR}/test/t2.ibd";
open(FILE, "+<$file") || die "Unable to open $file";
binmode FILE;
seek (FILE, $ENV{INNODB_PAGE_SIZE} * 4, SEEK_SET) or die "seek";
print FILE "junk";
close FILE or die "close";
EOF
 
--source include/start_mysqld.inc
 
eval load data infile '$MYSQLTEST_VARDIR/tmp/t1.outfile' into table t2;
failed: 1296: Got error 192 'Table encrypted but decryption failed. This could be because correct encryption management plugin is not loaded, used encryption key is not available or encryption method does not match.' from InnoDB
 
show warnings;
Level	Code	Message
Warning	192	Table t2 in file ./test/t2.ibd is encrypted but encryption service or used key_id 1 is not available.  Can't continue reading table.
Error	1296	Got error 192 'Table encrypted but decryption failed. This could be because correct encryption management plugin is not loaded, used encryption key is not available or encryption method does not match.' from InnoDB

The following error in the log file:

2019-05-02 23:32:57 1 [ERROR] InnoDB: The page [page id: space=6, page number=4] in file './test/t2.ibd' cannot be decrypted.
2019-05-02 23:32:57 1 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2019-05-02 23:32:57 1 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2019-05-02 23:32:57 1 [ERROR] InnoDB: The page [page id: space=6, page number=4] in file './test/t2.ibd' cannot be decrypted.
2019-05-02 23:32:57 1 [Note] InnoDB: However key management plugin or used key_version 1 is not found or used encryption algorithm or method does not match.
2019-05-02 23:32:57 1 [Note] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
2019-05-02 23:32:57 1 [ERROR] InnoDB: The page [page id: space=6, page number=4] in file './test/t2.ibd' cannot be decrypted.

Comment by Thirunarayanan Balathandayuthapani [ 2019-05-02 ]

Problem is that particular page got corrupted. When encrypted page got corrupted then the server gives the above error only.
buf_page_t contains encrypted variable to indicate the page is encrypted or not. Trying to remove the variable from it.

Comment by Marko Mäkelä [ 2019-10-03 ]

It is possible that MDEV-12699 (which was pushed to 10.2.24,10.3.15,10.4.5) made obsolete the field buf_page_t::encrypted that was added as part of MDEV-8588.

Comment by Matthias Leich [ 2019-10-08 ]

Preliminary result of RQG testing:
~ 680 tests executed
1 test --> https://jira.mariadb.org/browse/MDEV-20775
48 --> RQG declares a deadlock because observing in processlist states like (snip of RQG log)
Reporter 'Deadlock': Content of processlist ---------- begin
Reporter 'Deadlock': ID -- COMMAND -- TIME -- INFO -- state
Reporter 'Deadlock': 1 -- Daemon -- <undef> -- <undef> -- ok
Reporter 'Deadlock': 3 -- Daemon -- <undef> -- <undef> -- ok
Reporter 'Deadlock': 4 -- Daemon -- <undef> -- <undef> -- ok
Reporter 'Deadlock': 2 -- Daemon -- <undef> -- <undef> -- ok
Reporter 'Deadlock': 5 -- Daemon -- <undef> -- <undef> -- ok
Reporter 'Deadlock': 8 -- Sleep -- 241 -- <undef> -- ok
Reporter 'Deadlock': 17 -- Query -- 64 -- ALTER TABLE `t8` ROW_FORMAT=COMPRESSED ROW_FORMAT=DYNAMIC /* E_R Thread5 QNO 1638 CON_ID 17 */ -- ok
Reporter 'Deadlock': 18 -- Query -- 8 -- FLUSH TABLES /* E_R Thread8 QNO 1619 CON_ID 18 */ -- ok
Reporter 'Deadlock': 20 -- Query -- 41 -- ALTER TABLE `t8` PAGE_COMPRESSED=1 /* E_R Thread10 QNO 1634 CON_ID 20 */ -- ok
Reporter 'Deadlock': 21 -- Query -- 124 -- ALTER TABLE `t8` ENCRYPTION_KEY_ID=6 /* E_R Thread2 QNO 1638 CON_ID 21 */ -- stalled?
Reporter 'Deadlock': 19 -- Query -- 6 -- UPDATE `t8` SET `c` = 'p' WHERE `id` = 42711 /* E_R Thread9 QNO 1657 CON_ID 19 */ -- ok
Reporter 'Deadlock': 24 -- Query -- 124 -- ALTER TABLE `t8` ENCRYPTED=YES ENCRYPTED=YES /* E_R Thread6 QNO 1609 CON_ID 24 */ -- stalled?
Reporter 'Deadlock': 25 -- Query -- 31 -- ALTER TABLE `t8` FORCE /* E_R Thread1 QNO 1640 CON_ID 25 */ -- ok
Reporter 'Deadlock': 23 -- Query -- 8 -- INSERT IGNORE INTO `t8` ( `id`, `k`) VALUES ( NULL, 1574502400 ) /* E_R Thread4 QNO 1669 CON_ID 23 */ -- ok
Reporter 'Deadlock': 22 -- Query -- 6 -- UPDATE IGNORE `t8` SET `id` = `k` + 1 WHERE `id` = 50504 /* E_R Thread3 QNO 1701 CON_ID 22 */ -- ok
Reporter 'Deadlock': 28 -- Query -- 8 -- ALTER TABLE `t8`  /* E_R Thread11 QNO 1691 CON_ID 28 */ -- ok
Reporter 'Deadlock': 27 -- Query -- 6 -- ALTER TABLE `t8` FORCE /* E_R Thread12 QNO 1643 CON_ID 27 */ -- ok
Reporter 'Deadlock': 26 -- Query -- 37 -- ALTER TABLE `t8` FORCE /* E_R Thread13 QNO 1634 CON_ID 26 */ -- ok
Reporter 'Deadlock': 29 -- Query -- 6 -- DELETE FROM `t8` WHERE `id` = 20174 /* E_R Thread7 QNO 1657 CON_ID 29 */ -- ok
Reporter 'Deadlock': 54 -- Query -- 0 -- SHOW FULL PROCESSLIST -- ok
Reporter 'Deadlock': Content of processlist ---------- end
ERROR: Reporter 'Deadlock': 2 stalled queries detected, declaring deadlock at DSN dbi:mysql:host=127.0.0.1:port=28840:user=root:database=test:mysql_local_infile=1. Will exit with STATUS_SERVER_DEADLOCKED later.
 
Running the same test against
- some actual 10.2 showed the same RQG Deadlocks.  But less frequent (~ 20 of ~ 700 runs).
- bb-10.2-merge without MDEV-19335 patches showed the same RQG Deadlocks.
   But a bit less frequent (~ 37 of ~ 700 runs).
So the MDEV-19335 patches cannot be called guilty.

Generated at Thu Feb 08 08:50:53 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.