Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-8727

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

        Details

        • 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.

            Gliffy Diagrams

              Attachments

                Activity

                Ascending order - Click to sort in descending order
                Hide
                Permalink
                elenst Elena Stepanova added a comment - - edited

                Jan Lindström,

                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
                Show
                elenst Elena Stepanova added a comment - - edited Jan Lindström , 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
                Hide
                Permalink
                jplindst Jan Lindström added a comment -

                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.

                Show
                jplindst Jan Lindström added a comment - 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.

                  People

                  • Assignee:
                    jplindst Jan Lindström
                    Reporter:
                    elenst Elena Stepanova
                  • Votes:
                    0 Vote for this issue
                    Watchers:
                    2 Start watching this issue

                    Dates

                    • Created:
                      Updated:
                      Resolved:

                      Time Tracking

                      Estimated:
                      Original Estimate - Not Specified
                      Not Specified
                      Remaining:
                      Remaining Estimate - 0 minutes
                      0m
                      Logged:
                      Time Spent - 2 days, 4 hours
                      2d 4h

                        Agile