Prepare skips rollback on encrypted tables and completes successfully if keyring plugin is not loaded
Description
Environment
AFFECTED CS IDs
Activity
Satya Bodapati August 21, 2023 at 10:24 AM
we have fixed this escalation https://jira.percona.com/browse/PXB-3079 in 8.0.34-29 release.
It is not simply about converting ERROR to a WARNING.
If there is a redo on encrypted tablespace and no keyring -> PXB ERRORed out (already)
If there is no redo on encrypted tablespace but there is rollback -> PXB did NOT ERROR out.
We also have improved upon 2.4 behaviour. ie
If there is an encrypted tablespace on which is NO redo and undo (rollback) -> PXB 2.4 would still fail even if there is no rollback on the encrypted tablespaces.
From 8.0.34, If there are encrypted tables and there is NO undo or redo, lack of keyring wouldn't fail the prepare.
In https://perconadev.atlassian.net/browse/PXB-3079#icft=PXB-3079, please see https://github.com/percona/percona-xtrabackup/pull/1480 for more details.
Satya Bodapati July 25, 2023 at 1:00 PMEdited
2023-07-25T13:58:20.063397+01:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 1 for sys/sys_config, old maximum was 0
2023-07-25T13:58:20.063859+01:00 0 [ERROR] [MY-012657] [InnoDB] Encryption can't find master key, please check the keyring is loaded.
2023-07-25T13:58:20.063872+01:00 0 [ERROR] [MY-012226] [InnoDB] Encryption information in datafile: ./test/t1.ibd can't be decrypted, please confirm that keyring is loaded.
2023-07-25T13:58:20.063881+01:00 0 [Note] [MY-011825] [Xtrabackup] Failed to decrypt table ./test/t1.ibd with space id 8. Will check if encrytion key has been parsed at the end of backup.
2023-07-25T13:58:20.063895+01:00 0 [Note] [MY-011825] [Xtrabackup] Unable to open tablespace 'test/t1.ibd'. Possibly dropped. InnoDB DB_ error code is 113
2023-07-25T13:58:20.063981+01:00 0 [Note] [MY-011825] [Xtrabackup] Completed loading of 9 tablespaces into cache in 0.000658159 seconds
2023-07-25T13:58:20.290534+01:00 0 [Note] [MY-011825] [Xtrabackup] Time taken to build dictionary: 0.226515 seconds
2023-07-25T13:58:20.290699+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291115+01:00 0 [Note] [MY-013014] [InnoDB] Starting in background the rollback of uncommitted transactions
2023-07-25T13:58:20.291171+01:00 0 [Note] [MY-013011] [InnoDB] Rolling back trx with id 1580, 21 rows to undo
2023-07-25T13:58:20.291307+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291366+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291424+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291475+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291519+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291618+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291647+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291685+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291729+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291789+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291818+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291855+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291904+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.291934+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292012+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292043+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292073+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292103+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292164+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292194+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.292225+01:00 0 [Warning] [MY-011825] [Xtrabackup] Unable to load table with table_id 1069 InnoDB DB_ Error code is 44
2023-07-25T13:58:20.303499+01:00 0 [Note] [MY-013012] [InnoDB] Rollback of trx with id 1580 completed
2023-07-25T13:58:20.303568+01:00 0 [Note] [MY-013015] [InnoDB] Rollback of non-prepared transactions completed
2023-07-25T13:58:20.305604+01:00 0 [Note] [MY-011825] [Xtrabackup] starting shutdown with innodb_fast_shutdown = 1
2023-07-25T13:58:20.305719+01:00 0 [Note] [MY-012330] [InnoDB] FTS optimize thread exiting.
2023-07-25T13:58:21.291844+01:00 0 [Note] [MY-013072] [InnoDB] Starting shutdown...During the tablespace loading stage to cache(IBD to fil_space_t), we do see the problem and throw an error and the tablespace is NOT loaded to cache.
Later, during rollback, since the tablespace is not in cache, we consider the tablespace as possibly dropped.
Satya Bodapati July 25, 2023 at 12:58 PM
This issue exists on all 8.0 versions. PXB throws an error if there is a redo on the table but unfortunately it doesn't if there is a rollback on the table.
Satya Bodapati July 20, 2023 at 11:16 AM
Like user said, 2.4 throws the errors like this.
nnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
InnoDB: Highest supported file format is Barracuda.
InnoDB: Encryption can't find master key, please check the keyring plugin is loaded.
InnoDB: Encryption information in datafile: ./test/t1.ibd can't be decrypted, please check if a keyring plugin is loaded and initialized successfully.Checking the first 8.0 behaviour
Satya Bodapati July 20, 2023 at 10:38 AM
btw, https://perconadev.atlassian.net/browse/PXB-1497#icft=PXB-1497 has no relation to this bug. The only similarity is that xtrabackup returns exit code as 0 when xtrabackup detected ERROR. Am currently verifying the 2.4.* behaviour
https://perconadev.atlassian.net/browse/PXB-1497#icft=PXB-1497 seems to be reproducible with latest 8.0.33.
Steps to reproduce:
01) Take a backup from an instance with encrypted tables.
02) Try to prepare it with explicitly mentioned keyring (without a valid key). For instance:
PXB run
$ bin/xtrabackup --defaults-file=/home/iwo/sandboxes/msb_8_0_32/my.sandbox.cnf --xtrabackup-plugin-dir=$(pwd)/lib/plugin -S /tmp/mysql_sandbox8032.sock --prepare --keyring-file-data=/dev/null --target-dir=a … 2023-07-04T17:29:02.182202+02:00 0 [Note] [MY-012976] [InnoDB] 8.0.33 started; log sequence number 19863062 2023-07-04T17:29:02.182467+02:00 0 [Warning] [MY-012091] [InnoDB] Allocated tablespace ID 1 for sys/sys_config, old maximum was 0 2023-07-04T17:29:02.182713+02:00 0 [ERROR] [MY-012226] [InnoDB] Encryption information in datafile: ./test/A.ibd can't be decrypted, please confirm that keyring is loaded. 2023-07-04T17:29:02.182723+02:00 0 [Note] [MY-011825] [Xtrabackup] Failed to decrypt table ./test/A.ibd with space id 6. Will check if encrytion key has been parsed at the end of backup. 2023-07-04T17:29:02.197174+02:00 0 [Note] [MY-011825] [Xtrabackup] starting shutdown with innodb_fast_shutdown = 1 2023-07-04T17:29:02.197278+02:00 0 [Note] [MY-012330] [InnoDB] FTS optimize thread exiting. 2023-07-04T17:29:03.197330+02:00 0 [Note] [MY-013072] [InnoDB] Starting shutdown... 2023-07-04T17:29:03.213007+02:00 0 [Note] [MY-013084] [InnoDB] Log background threads are being closed... 2023-07-04T17:29:03.221855+02:00 0 [Note] [MY-012980] [InnoDB] Shutdown completed; log sequence number 19863062 2023-07-04T17:29:03.223124+02:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'keyring_file' 2023-07-04T17:29:03.223282+02:00 0 [Note] [MY-010733] [Server] Shutting down plugin 'daemon_keyring_proxy_plugin' 2023-07-04T17:29:03.223464+02:00 0 [Note] [MY-011825] [Xtrabackup] completed OK!That
completed OK!message and RC=0 makes it very hard to catch in any automated environment.