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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: N/A
Fix Version/s: 10.1.8
Component/s: Encryption, Storage Engine - InnoDB
Labels:
None

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.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

threads1
16 kB
2015-09-02 03:08

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2015-09-02 03:09

Elena Stepanova made changes - 2015-09-02 03:09

Field	Original Value	New Value
Link		This issue relates to TODO-699 [ TODO-699 ]

Jan Lindström (Inactive) made changes - 2015-09-07 09:17

Status

Open [ 1 ]

In Progress [ 3 ]

Elena Stepanova added a comment - 2015-09-27 00:38 - edited

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

Elena Stepanova added a comment - 2015-09-27 00:38 - edited 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

Rasmus Johansson (Inactive) made changes - 2015-09-30 11:10

Sprint

10.1.8-4 [ 16 ]

Rasmus Johansson (Inactive) made changes - 2015-09-30 11:10

Rank

Ranked higher

Jan Lindström (Inactive) added a comment - 2015-10-01 08:32

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.

Jan Lindström (Inactive) added a comment - 2015-10-01 08:32 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.

Jan Lindström (Inactive) made changes - 2015-10-01 08:32

Fix Version/s		10.1.8 [ 19605 ]
Fix Version/s	10.1 [ 16100 ]
Resolution		Fixed [ 1 ]
Status	In Progress [ 3 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:41

Workflow

MariaDB v3 [ 71329 ]

MariaDB v4 [ 149551 ]

People

Assignee:: Jan Lindström (Inactive)

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2015-09-02 03:09

Updated:: 2015-10-01 08:32

Resolved:: 2015-10-01 08:32

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Activity

People

Dates

Git Integration