[MDEV-8727] Server/InnoDB hangs on shutdown after trying to read an encrypted table with a wrong key Created: 2015-09-02  Updated: 2015-10-01  Resolved: 2015-10-01

Status: Closed
Project: MariaDB Server
Component/s: Encryption, Storage Engine - InnoDB
Affects Version/s: N/A
Fix Version/s: 10.1.8

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Attachments: HTML File threads1    
Issue Links:
Relates
Sprint: 10.1.8-4

 Description   

Test flow

 
# - start server with key file containing key 4;
 
# - create an encrypted InnoDB table with key 4, insert some data;
 
# - restart server with a different key 4;
 
# - try to read the table (causes an error, it's expected);
 
# - try to shutdown the server
 
# - => shutdown does not finish

Draft test case

 
--echo # 
--echo # Restart the server with key 4 in the key file
 
--echo # 
 
 
--source include/have_innodb.inc
 
 
 
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--shutdown_server
 
--source include/wait_until_disconnected.inc
 
 
 
--write_file $MYSQLTEST_VARDIR/keys1.txt
 
1;770A8A65DA156D24EE2A093277530142
 
4;18420B5CBA31CCDFFE9716E91EB61374D05914F3ADE23E03
 
EOF
 
 
 
--exec echo "restart:--plugin-load-add=file_key_management.so --file-key-management --file-key-management-filename=$MYSQLTEST_VARDIR/keys1.txt" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--enable_reconnect
 
--source include/wait_until_connected_again.inc
 
 
 
CREATE TABLE t1 (i INT, KEY(i)) ENGINE=InnoDB ENCRYPTED=YES ENCRYPTION_KEY_ID=4;
 
INSERT INTO t1 VALUES (1);
 
 
 
--echo # 
--echo # Restart the server with a different value for key 4 in the key file
 
--echo # 
 
 
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--shutdown_server
 
--source include/wait_until_disconnected.inc
 
 
 
--write_file $MYSQLTEST_VARDIR/keys2.txt
 
1;770A8A65DA156D24EE2A093277530142
 
4;22222222222222222222222222222222
 
EOF
 
 
 
--exec echo "restart:--plugin-load-add=file_key_management.so --file-key-management --file-key-management-filename=$MYSQLTEST_VARDIR/keys2.txt" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--enable_reconnect
 
--source include/wait_until_connected_again.inc
 
 
 
--error ER_NO_SUCH_TABLE_IN_ENGINE
 
SELECT * FROM t1;
 
 
 
--echo #
 
--echo # Try to shutdown the server with 20 sec timeout.
 
--echo # After the timeout, check the error log to see that shutdown did not complete
 
--echo #
 
--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 
--shutdown_server 20
 
--source include/wait_until_disconnected.inc
 
 
 
--cat_file $MYSQLTEST_VARDIR/log/mysqld.1.err

Last words in the error log

 
2015-09-02  3:01:52 140617850021632 [Note] InnoDB: FTS optimize thread exiting.
 
2015-09-02  3:01:52 140618217424640 [Note] InnoDB: Starting shutdown...

Stack trace from bb-10.1-jan-encryption 549ed8c69b29050135bcdd045870dccd56b46d3b

 
Thread 2 (Thread 0x7effe0960700 (LWP 11513)):
 
#0  0x00007effde47b453 in select () at ../sysdeps/unix/syscall-template.S:82
 
#1  0x00007effe139ed6f in os_thread_sleep (tm=100000) at /home/elenst/git/bb-10.1-jan-encryption/storage/xtradb/os/os0thread.cc:285
 
#2  0x00007effe1377aea in logs_empty_and_mark_files_at_shutdown () at /home/elenst/git/bb-10.1-jan-encryption/storage/xtradb/log/log0log.cc:3557
 
#3  0x00007effe146932b in innobase_shutdown_for_mysql () at /home/elenst/git/bb-10.1-jan-encryption/storage/xtradb/srv/srv0start.cc:3140
 
#4  0x00007effe12fd9c4 in innobase_end (hton=0x7effdd82e270, type=HA_PANIC_CLOSE) at /home/elenst/git/bb-10.1-jan-encryption/storage/xtradb/handler/ha_innodb.cc:4189
 
#5  0x00007effe114b5de in ha_finalize_handlerton (plugin=0x7effdd9446e8) at /home/elenst/git/bb-10.1-jan-encryption/sql/handler.cc:452
 
#6  0x00007effe0f2cb16 in plugin_deinitialize (plugin=0x7effdd9446e8, ref_check=true) at /home/elenst/git/bb-10.1-jan-encryption/sql/sql_plugin.cc:1209
 
#7  0x00007effe0f2cf59 in reap_plugins () at /home/elenst/git/bb-10.1-jan-encryption/sql/sql_plugin.cc:1287
 
#8  0x00007effe0f2edec in plugin_shutdown () at /home/elenst/git/bb-10.1-jan-encryption/sql/sql_plugin.cc:1934
 
#9  0x00007effe0e48e11 in clean_up (print_message=true) at /home/elenst/git/bb-10.1-jan-encryption/sql/mysqld.cc:2103
 
#10 0x00007effe0e48a48 in unireg_end () at /home/elenst/git/bb-10.1-jan-encryption/sql/mysqld.cc:1993
 
#11 0x00007effe0e4896a in kill_server (sig_ptr=0x0) at /home/elenst/git/bb-10.1-jan-encryption/sql/mysqld.cc:1921
 
#12 0x00007effe0e48987 in kill_server_thread (arg=0x7effe09f1dd0) at /home/elenst/git/bb-10.1-jan-encryption/sql/mysqld.cc:1944
 
#13 0x00007effe05f5b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
 
#14 0x00007effde48195d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
 
#15 0x0000000000000000 in ?? ()
 
 
 
Thread 1 (Thread 0x7effe0a06760 (LWP 11470)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
 
#1  0x00007effe17a612a in safe_cond_wait (cond=0x7effe2246b20, mp=0x7effe22458e0, file=0x7effe183dda0 "/home/elenst/git/bb-10.1-jan-encryption/include/mysql/psi/mysql_thread.h", line=1165) at /home/elenst/git/bb-10.1-jan-encryption/mysys/thr_mutex.c:493
 
#2  0x00007effe0e45c0c in inline_mysql_cond_wait (that=0x7effe2246b20, mutex=0x7effe22458e0, src_file=0x7effe183fa60 "/home/elenst/git/bb-10.1-jan-encryption/sql/mysqld.cc", src_line=5920) at /home/elenst/git/bb-10.1-jan-encryption/include/mysql/psi/mysql_thread.h:1165
 
#3  0x00007effe0e50259 in mysqld_main (argc=21, argv=0x7effdd81e8c0) at /home/elenst/git/bb-10.1-jan-encryption/sql/mysqld.cc:5920
 
#4  0x00007effe0e45530 in main (argc=11, argv=0x7ffc62c34e08) at /home/elenst/git/bb-10.1-jan-encryption/sql/main.cc:25

All threads' stack trace is attached.

 Comments   
Comment by Elena Stepanova [ 2015-09-27 ]

jplindst,

I remember you asked me about some bug, whether it was hanging or just slow.
If it was about this one, I double-checked manually, without MTR, but otherwise the same scenario. I gave it 5 minutes and it still did not shutdown (normally takes ~2 seconds), so I guess it really hangs. 

~/git/10.1$ tail data/log.err
 
2015-09-27  0:30:12 140142062585600 [ERROR] InnoDB: However key management plugin or used key_id 1 is not found or used encryption algorithm or method does not match.
 
2015-09-27  0:30:12 140142062585600 [ERROR] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
 
2015-09-27  0:30:12 140142062585600 [ERROR] InnoDB: Block in space_id 4 in file test/t1 encrypted.
 
2015-09-27  0:30:12 140142062585600 [ERROR] InnoDB: However key management plugin or used key_id 1 is not found or used encryption algorithm or method does not match.
 
2015-09-27  0:30:12 140142062585600 [ERROR] InnoDB: Marking tablespace as missing. You may drop this table or install correct key management plugin and key file.
 
2015-09-27  0:30:18 140142062286592 [Note] /home/elenst/git/10.1/sql/mysqld: Normal shutdown
 
 
 
2015-09-27  0:30:18 140142062286592 [Note] Event Scheduler: Purging the queue. 0 events
 
2015-09-27  0:30:18 140141314168576 [Note] InnoDB: FTS optimize thread exiting.
 
2015-09-27  0:30:18 140142062286592 [Note] InnoDB: Starting shutdown...
 
~/git/10.1$ date
 
Sun Sep 27 00:35:26 MSK 2015

Comment by Jan Lindström (Inactive) [ 2015-10-01 ]

commit 3266216f2c8f90c866b371fbd4a8bf6b0c628996
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Thu Oct 1 08:16:14 2015 +0300

MDEV-8727: Server/InnoDB hangs on shutdown after trying to read an encrypted table with a wrong key

Analysis: When a page is read from encrypted table and page can't be
decrypted because of bad key (or incorrect encryption algorithm or
method) page was incorrectly left on buffer pool.

Fix: Remove page from buffer pool and from pending IO.

Generated at Thu Feb 08 07:29:19 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.