Details
-
Bug
-
Status: Closed (View Workflow)
-
Minor
-
Resolution: Fixed
-
10.1(EOL), 10.5, 10.6, 10.7(EOL), 10.8(EOL)
-
None
Description
Start server with
--plugin-load-add=file_key_management --plugin-load-add=example_key_management --innodb-encrypt-tables --innodb-encryption-threads=1
|
otherwise defaults.
Doesn't matter whether file-key-management-filename is provided or not.
|
Error log after startup |
2016-04-19 20:38:43 139999079106432 [ERROR] Plugin 'file_key_management' registration as a ENCRYPTION failed.
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: The InnoDB memory heap is disabled
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Memory barrier is not used
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Compressed tables use zlib 1.2.8
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Using Linux native AIO
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Using generic crc32 instructions
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Initializing buffer pool, size = 128.0M
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Completed initialization of buffer pool
|
2016-04-19 20:38:43 139999079106432 [Note] InnoDB: Highest supported file format is Barracuda.
|
2016-04-19 20:38:45 139999079106432 [Note] InnoDB: 128 rollback segment(s) are active.
|
2016-04-19 20:38:45 139999079106432 [Note] InnoDB: Waiting for purge to start
|
2016-04-19 20:38:45 139999079106432 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.28-76.1 started; log sequence number 1616819
|
2016-04-19 20:38:45 139999079106432 [Note] InnoDB: Creating #1 thread id 139998336632576 total threads 1.
|
2016-04-19 20:38:45 139998361810688 [Note] InnoDB: Dumping buffer pool(s) not yet started
|
2016-04-19 20:38:45 139999079106432 [Note] Plugin 'FEEDBACK' is disabled.
|
2016-04-19 20:38:45 139999079106432 [Note] Server socket created on IP: '::'.
|
2016-04-19 20:38:45 139999079106432 [Note] /bld/10.1/bin/mysqld: ready for connections.
|
Version: '10.1.13-MariaDB-debug' socket: '/bld/10.1/data/tmp/mysql.sock' port: 3306 Source distribution
|
Run
SELECT COUNT(*) FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_ENCRYPTION; |
|
Stack trace from 10.1 commit 1cf852d874b0e82ebfa3854300abaacd04d3eb01 |
2016-04-19 20:31:09 139814445774592 [ERROR] InnoDB: Used key_id 1 can't be found from key file.
|
2016-04-19 20:31:09 7f29165ff700 InnoDB: Assertion failure in thread 139814445774592 in file fil0crypt.cc line 994
|
InnoDB: Failing assertion: new_state->key_version != ENCRYPTION_KEY_VERSION_INVALID
|
|
|
#5 0x00007f2940b0e538 in abort () from /lib64/libc.so.6
|
#6 0x000056211447fa76 in fil_crypt_get_key_state (new_state=0x7f29165fee00) at /src/10.1/storage/xtradb/fil/fil0crypt.cc:994
|
#7 0x00005621144803e4 in fil_crypt_space_needs_rotation (state=0x7f29165fee10, key_state=0x7f29165fee00, recheck=0x7f29165fedeb) at /src/10.1/storage/xtradb/fil/fil0crypt.cc:1339
|
#8 0x0000562114480a61 in fil_crypt_find_space_to_rotate (key_state=0x7f29165fee00, state=0x7f29165fee10, recheck=0x7f29165fedeb) at /src/10.1/storage/xtradb/fil/fil0crypt.cc:1587
|
#9 0x00005621144820a5 in fil_crypt_thread (arg=0x0) at /src/10.1/storage/xtradb/fil/fil0crypt.cc:2260
|
#10 0x00007f2942a4f0a4 in start_thread () from /lib64/libpthread.so.0
|
#11 0x00007f2940bbd04d in clone () from /lib64/libc.so.6
|
Attachments
Issue Links
- relates to
-
MDEV-9909 Enable plugins for MTR
-
- Closed
-
-
-
- Closed
-
-
-
- Open
-
Activity
On 10.6 and later, for the test case, the call stack where the object was initialized is related to MDEV-24626:
|
10.6 f7f0bc748e88f911b957d3dbf3bc0828a33675fb |
#0 fil_space_crypt_t::fil_space_crypt_t (new_encryption=FIL_ENCRYPTION_ON, new_key_id=<optimized out>, new_min_key_version=0, new_type=0, this=0x55ba3d52d800)
|
at /mariadb/10.6/storage/innobase/include/fil0crypt.h:128
|
#1 fil_space_create_crypt_data (type=0, min_key_version=0, key_id=<optimized out>, encrypt_mode=FIL_ENCRYPTION_ON) at /mariadb/10.6/storage/innobase/fil/fil0crypt.cc:226
|
#2 fil_space_create_crypt_data (key_id=<optimized out>, encrypt_mode=FIL_ENCRYPTION_ON) at /mariadb/10.6/storage/innobase/fil/fil0crypt.cc:245
|
#3 fil_space_read_crypt_data (zip_size=<optimized out>, page=page@entry=0x7ff359cfc000 "") at /mariadb/10.6/storage/innobase/fil/fil0crypt.cc:313
|
#4 0x000055ba3a2d5fe9 in recv_sys_t::recover_deferred (this=<optimized out>, p=<optimized out>, name="./test/t1.ibd", free_block=<optimized out>) at /mariadb/10.6/storage/innobase/log/log0recv.cc:897
|
#5 0x000055ba3a2dba33 in reinit_all (this=<optimized out>) at /mariadb/10.6/storage/innobase/log/log0recv.cc:757
|
I will check an older version to get a simpler view of this.
Before MDEV-12353 in 10.5, preparing a backup would fail due to the following:
case MLOG_FILE_WRITE_CRYPT_DATA: |
dberr_t err;
|
ptr = const_cast<byte*>(fil_parse_write_crypt_data(ptr, end_ptr, &err)); |
|
|
if (err != DB_SUCCESS) { |
recv_sys->found_corrupt_log = TRUE;
|
}
|
break; |
|
10.3 f130a5ea3c1cc504acecbad7615fb27c6e28dbfa |
2022-04-14 12:11:57 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1636426
|
2022-04-14 12:11:57 0 [ERROR] InnoDB: ############### CORRUPT LOG RECORD FOUND ##################
|
2022-04-14 12:11:57 0 [Note] InnoDB: Log record type 100, page 5:0. Log parsing proceeded successfully up to 1636494. Previous log record type 1, is multi 1 Recv offset 527, prev 521
|
I do not think that it makes sense to address that error in the older versions.
Starting with 10.5 the assertion failure occurs during page flushing. The invalid object was initialized here:
|
10.5 e41500e4f2914af8142e06ca17925f6c03c7b7af |
#0 fil_space_crypt_t::fil_space_crypt_t (this=0x55b1dd1fee50, new_type=0,
|
new_min_key_version=<optimized out>, new_key_id=1,
|
new_encryption=FIL_ENCRYPTION_ON)
|
at /mariadb/10.5m/storage/innobase/include/fil0crypt.h:128
|
#1 0x000055b1dad33dc0 in fil_space_create_crypt_data (type=type@entry=0,
|
encrypt_mode=FIL_ENCRYPTION_ON, min_key_version=min_key_version@entry=0,
|
key_id=1) at /mariadb/10.5m/storage/innobase/fil/fil0crypt.cc:218
|
#2 0x000055b1dad33de3 in fil_space_create_crypt_data (
|
encrypt_mode=<optimized out>, key_id=<optimized out>)
|
at /mariadb/10.5m/storage/innobase/fil/fil0crypt.cc:243
|
#3 0x000055b1dad33eaf in fil_space_read_crypt_data (zip_size=<optimized out>,
|
page=0x55b1dd21c000 "")
|
at /mariadb/10.5m/storage/innobase/fil/fil0crypt.cc:311
|
#4 0x000055b1dad279a9 in fil_ibd_load (space_id=5, filename=<optimized out>,
|
space=@0x7ffe724b95f8: 0x0)
|
at /mariadb/10.5m/storage/innobase/fil/fil0fil.cc:3118
|
#5 0x000055b1dadf38e0 in fil_name_process (name=<optimized out>,
|
name@entry=0x7fb60376801c "./test/t1.ibd", len=len@entry=13,
|
space_id=<optimized out>, deleted=deleted@entry=false)
|
at /mariadb/10.5m/storage/innobase/log/log0recv.cc:834
|
#6 0x000055b1dadf5769 in recv_sys_t::parse (
|
this=this@entry=0x55b1db9198c0 <recv_sys>, checkpoint_lsn=47846,
|
store=store@entry=0x7ffe724b9ce4, apply=apply@entry=true)
|
I believe that an appropriate fix is to treat the file as if it was corrupted or non-existing when the encryption key is unavailable. Recovery would only succeed if innodb_force_recovery is set, and any recovered log records for the file would be ignored.
For a while, I was thinking if it would be better if mariadb-backup should fail to start up if the encryption plugin fails to load, like it does with the test case. Then I realized that also a properly working encryption plugin could fail to find a specific key. In the test case, it is one of the fallback stubs no_key() or no_get_key() that will be invoked.
The following fixes the test case for me. It should also fix crash recovery:
diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc
|
index 94ea5182d35..5f5732a2a09 100644
|
--- a/storage/innobase/fil/fil0fil.cc
|
+++ b/storage/innobase/fil/fil0fil.cc
|
@@ -3118,6 +3118,10 @@ fil_ibd_load(
|
? fil_space_read_crypt_data(fil_space_t::zip_size(flags),
|
first_page)
|
: NULL;
|
+ if (crypt_data && !crypt_data->is_key_found()) {
|
+ return FIL_LOAD_INVALID;
|
+ }
|
+
|
space = fil_space_t::create(
|
file.name(), space_id, flags, FIL_TYPE_TABLESPACE, crypt_data);
|
|
|
When it comes to creating a proper test case, I would appreciate some help. Otherwise, I would push this without a test case.
|
10.5 e41500e4f2914af8142e06ca17925f6c03c7b7af with the above patch |
…
|
/dev/shm/10.5m/extra/mariabackup/mariabackup: Can't find file: '/dev/shm/10.5m/mysql-test/var/tmp/mykeys.txt' (errno: 2 "No such file or directory")
|
2022-04-14 17:37:26 0 [ERROR] Plugin 'file_key_management' init function returned error.
|
2022-04-14 17:37:26 0 [ERROR] Plugin 'file_key_management' registration as a ENCRYPTION failed.
|
[00] 2022-04-14 17:37:26 This target seems to be not prepared yet.
|
[00] 2022-04-14 17:37:26 mariabackup: using the following InnoDB configuration for recovery:
|
[00] 2022-04-14 17:37:26 innodb_data_home_dir = .
|
[00] 2022-04-14 17:37:26 innodb_data_file_path = ibdata1:12M:autoextend
|
[00] 2022-04-14 17:37:26 innodb_log_group_home_dir = .
|
[00] 2022-04-14 17:37:26 InnoDB: Using Linux native AIO
|
[00] 2022-04-14 17:37:26 Starting InnoDB instance for recovery.
|
[00] 2022-04-14 17:37:26 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
|
2022-04-14 17:37:26 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
|
2022-04-14 17:37:26 0 [Note] InnoDB: Uses event mutexes
|
2022-04-14 17:37:26 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2022-04-14 17:37:26 0 [Note] InnoDB: Number of pools: 1
|
2022-04-14 17:37:26 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2022-04-14 17:37:26 0 [Note] InnoDB: Using Linux native AIO
|
2022-04-14 17:37:26 0 [Note] InnoDB: Initializing buffer pool, total size = 104857600, chunk size = 104857600
|
2022-04-14 17:37:26 0 [Note] InnoDB: Completed initialization of buffer pool
|
2022-04-14 17:37:26 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=47870,47870
|
2022-04-14 17:37:26 0 [Warning] InnoDB: We do not continue the crash recovery, because the table may become corrupt if we cannot apply the log records in the InnoDB log to it. To fix the problem and start mysqld:
|
2022-04-14 17:37:26 0 [Note] InnoDB: 1) If there is a permission problem in the file and mysqld cannot open the file, you should modify the permissions.
|
2022-04-14 17:37:26 0 [Note] InnoDB: 2) If the tablespace is not needed, or you can restore an older version from a backup, then you can remove the .ibd file, and use --innodb_force_recovery=1 to force startup without this file.
|
2022-04-14 17:37:26 0 [Note] InnoDB: 3) If the file system or the disk is broken, and you cannot remove the .ibd file, you can set --innodb_force_recovery.
|
2022-04-14 17:37:26 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1462] with error Generic error
|
[00] FATAL ERROR: 2022-04-14 17:37:26 mariabackup: innodb_init() returned 11 (Generic error).
|
mysqltest: At line 13: exec of '/dev/shm/10.5m/extra/mariabackup/mariabackup --prepare --target-dir=/dev/shm/10.5m/mysql-test/var/tmp/bk' failed, error: 256, status: 1, errno: 11
|
Output from before failure:
|
INSERT INTO t1 VALUES ('foo'),('bar');
|
The 10.6 version needed additional changes to the deferred recovery of tablespaces:
|
bb-10.6-MDEV-9948 50252088d5a2e202604462fb3b28e39923831642 |
2022-04-14 17:53:58 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=44267,44267
|
2022-04-14 17:53:58 0 [ERROR] InnoDB: Cannot apply log to [page id: space=5, page number=0] of corrupted file './test/t1.ibd'
|
2022-04-14 17:53:58 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1444] with error Data structure corruption
|
[00] FATAL ERROR: 2022-04-14 17:53:58 mariabackup: innodb_init() returned 37 (Data structure corruption).
|
Please test if that works for you, and if you can, create a polished test case. I think that recovery must succeed with innodb_force_recovery=1.
I modified the test encryption.innodb-redo-nokeys to cover this scenario. The test was flawed in a number of ways. It failed to ensure that InnoDB did not start, and it specified the parameter innodb_encrypt_tables=ON, which would cause InnoDB to refuse startup if the encryption plugin was not loaded. We want InnoDB to actually attempt startup and fail during the crash recovery.
Another case when the failure happens is if upon mariabackup prepare a key management plugin cannot be loaded on whatever reason. E.g. with file key management:
--source include/have_innodb.inc--exec echo "1;0123456789012345678901234567890A" > $MYSQL_TMP_DIR/mykeys.txt--let $restart_parameters= --plugin-load-add=file_key_management --file-key-management-filename=$MYSQL_TMP_DIR/mykeys.txt--source include/restart_mysqld.inc--exec $XTRABACKUP --backup -uroot --protocol=tcp --port=$MASTER_MYPORT --target-dir=$MYSQL_TMP_DIR/bk--remove_file $MYSQL_TMP_DIR/mykeys.txt--exec $XTRABACKUP --prepare --target-dir=$MYSQL_TMP_DIR/bk# Cleanup10.5 cfdb6212
2022-04-11 00:25:10 0x7fba02efb700 InnoDB: Assertion failure in file /data/src/10.5/storage/innobase/fil/fil0crypt.cc line 549InnoDB: Failing assertion: key_version != ENCRYPTION_KEY_VERSION_INVALIDInnoDB: We intentionally generate a memory trap.InnoDB: Submit a detailed bug report to https://jira.mariadb.org/InnoDB: If you get repeated assertion failures or crashes, evenInnoDB: immediately after the mysqld startup, there may beInnoDB: corruption in the InnoDB tablespace. Please refer toInnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/InnoDB: about forcing recovery.220411 0:25:10 [ERROR] mysqld got signal 6 ;This could be because you hit a bug. It is also possible that this binaryor one of the libraries it was linked against is corrupt, improperly built,or misconfigured. This error can also be caused by malfunctioning hardware.To report this bug, see https://mariadb.com/kb/en/reporting-bugsWe will try our best to scrape up some info that will hopefully helpdiagnose the problem, but since we have already crashed,something is definitely wrong and this may fail.Server version: 10.5.16-MariaDB-debugkey_buffer_size=0read_buffer_size=131072max_used_connections=0max_threads=1thread_count=0It is possible that mysqld could use up tokey_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6154 K bytes of memoryHope that's ok; if not, decrease some variables in the equation.Thread pointer: 0x0Attempting backtrace. You can use the following information to find outwhere mysqld died. If you see no messages after this, something wentterribly wrong...stack_bottom = 0x0 thread_stack 0x49000/mnt8t/bld/10.5-debug-nightly/bin/mariabackup(my_print_stacktrace+0x40)[0x5651d504f404]mysys/stacktrace.c:212(my_print_stacktrace)[0x5651d48096de]sigaction.c:0(__restore_rt)[0x7fba044c8140]linux/raise.c:51(__GI_raise)[0x7fba03ff7ce1]stdlib/abort.c:81(__GI_abort)[0x7fba03fe1537]ut/ut0mem.cc:45(ut_str3cat(char const*, char const*, char const*)::{lambda()#1}::operator()() const)[0x5651d4ef0792]fil/fil0crypt.cc:552(fil_encrypt_buf_for_full_crc32(fil_space_crypt_t*, unsigned long, unsigned long, unsigned long, unsigned char const*, unsigned char*))[0x5651d4c169ba]fil/fil0crypt.cc:598(fil_encrypt_buf(fil_space_crypt_t*, unsigned long, unsigned long, unsigned char const*, unsigned long, unsigned char*, bool))[0x5651d4c16bcb]fil/fil0crypt.cc:649(fil_space_encrypt(fil_space_t const*, unsigned long, unsigned char*, unsigned char*))[0x5651d4c16d97]buf/buf0flu.cc:723(buf_page_encrypt(fil_space_t*, buf_page_t*, unsigned char*, unsigned long*))[0x5651d4baa384]buf/buf0flu.cc:918(buf_flush_page(buf_page_t*, bool, fil_space_t*))[0x5651d4bab2a0]buf/buf0flu.cc:1519(buf_do_flush_list_batch(unsigned long, unsigned long))[0x5651d4bade2a]buf/buf0flu.cc:1595(buf_flush_list(unsigned long, unsigned long))[0x5651d4bae39c]buf/buf0flu.cc:2385(buf_flush_page_cleaner(void*))[0x5651d4bb1b0f]nptl/pthread_create.c:478(start_thread)[0x7fba044bcea7]x86_64/clone.S:97(__GI___clone)[0x7fba040b9def]The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ containsinformation that should help you find out what is causing the crash.Writing a core file...Working directory at /dev/shm/var_auto_JT0M/tmp/bkResource Limits:Limit Soft Limit Hard Limit UnitsMax cpu time unlimited unlimited secondsMax file size unlimited unlimited bytesMax data size unlimited unlimited bytesMax stack size 8388608 unlimited bytesMax core file size 0 unlimited bytesMax resident set unlimited unlimited bytesMax processes 385901 385901 processesMax open files 1024 1024 filesMax locked memory 12659513856 12659513856 bytesMax address space unlimited unlimited bytesMax file locks unlimited unlimited locksMax pending signals 385901 385901 signalsMax msgqueue size 819200 819200 bytesMax nice priority 0 0Max realtime priority 0 0Max realtime timeout unlimited unlimited usCore pattern: coreAlso happens with hashicorp plugin on 10.9.