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

    • 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

        Activity

          Ascending order - Click to sort in descending order
          elenst Elena Stepanova added a comment - - 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

          elenst Elena Stepanova added a comment - - 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
          jplindst Jan Lindström (Inactive) 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.

          jplindst Jan Lindström (Inactive) 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

            jplindst Jan Lindström (Inactive)
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

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