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

Assertion failure in file log0crypt.cc line 220 on server restart

    Details

    • Sprint:
      10.1.6-1

      Description

      If the server was previously started with InnoDB log encryption, restarting the server without the encryption plugin causes the assertion failure as below. On a release build, there is no assertion failure, but a crash with SIGABRT.

      I realize it cannot really work without the plugin on encrypted logs, and expect it to abort, but it would be good to have clear diagnostics for this rather than the scary crash.

      Also, I thought it might work with innodb_fast_shutdown turned off, but it doesn't make a difference.

      150513  3:32:01 [ERROR] InnoDB: Redo log crypto: getting mysqld crypto key from key version failed.
      2015-05-13 03:32:01 7f4331ff6760  InnoDB: Assertion failure in thread 139926578358112 in file log0crypt.cc line 220
      InnoDB: We intentionally generate a memory trap.
      
      Stack trace from 10.1 commit c8ad5b2f
      #5  0x00007f432fbd33e0 in *__GI_abort () at abort.c:92
      #6  0x00007f4332962742 in init_crypt_key (info=0x7ffce3e6e010) at 10.1/storage/xtradb/log/log0crypt.cc:220
      #7  0x00007f4332962884 in add_crypt_info (info=0x7ffce3e6e010) at 10.1/storage/xtradb/log/log0crypt.cc:254
      #8  0x00007f4332962fa3 in log_crypt_read_checkpoint_buf (buf=0x7f432f015b36 "") at 10.1/storage/xtradb/log/log0crypt.cc:474
      #9  0x00007f433295bcfb in recv_find_max_checkpoint (max_group=0x7ffce3e6eb58, max_field=0x7ffce3e6eb60) at 10.1/storage/xtradb/log/log0recv.cc:813
      #10 0x00007f433295fbac in recv_recovery_from_checkpoint_start_func (type=78656949, limit_lsn=18446744073709551615, min_flushed_lsn=1616911, max_flushed_lsn=1616911) at 10.1/storage/xtradb/log/log0recv.cc:3162
      #11 0x00007f4332a411dc in innobase_start_or_create_for_mysql () at 10.1/storage/xtradb/srv/srv0start.cc:2528
      #12 0x00007f43328d87fa in innobase_init (p=0x7f432f02e270) at 10.1/storage/xtradb/handler/ha_innodb.cc:4083
      #13 0x00007f433272c2f0 in ha_initialize_handlerton (plugin=0x7f432f1446e8) at 10.1/sql/handler.cc:512
      #14 0x00007f4332513fa8 in plugin_initialize (tmp_root=0x7ffce3e728e0, plugin=0x7f432f1446e8, argc=0x7f43337f59d0, argv=0x7f432f01e6c0, options_only=false) at 10.1/sql/sql_plugin.cc:1403
      #15 0x00007f4332514b7a in plugin_init (argc=0x7f43337f59d0, argv=0x7f432f01e6c0, flags=2) at 10.1/sql/sql_plugin.cc:1676
      #16 0x00007f43324363e7 in init_server_components () at 10.1/sql/mysqld.cc:5041
      #17 0x00007f4332437528 in mysqld_main (argc=12, argv=0x7f432f01e6c0) at 10.1/sql/mysqld.cc:5631
      #18 0x00007f433242d100 in main (argc=11, argv=0x7ffce3e73628) at 10.1/sql/main.cc:25
      

      To reproduce:

      • start server with
        [mysqld]
        plugin-load-add=file_key_management.so
        loose-file_key_management_filename=/home/elenst/git/10.1/mysql-test/std_data/keys.txt
        innodb-encrypt-log=on
        
      • shut down the server
      • start the server without the options above.

        Gliffy Diagrams

          Attachments

            Activity

            Hide
            jplindst Jan Lindström added a comment -

            commit f5ddffd83e627cc0f6a24dfe4d8fc2e0c983bf78
            Author: Jan Lindström <jan.lindstrom@mariadb.com>
            Date: Thu Jun 18 19:58:57 2015 +0300

            MDEV-8156: Assertion failure in file log0crypt.cc line 220 on server restart

            Instead of asserting print informative error message to error log
            and return failure from innodb_init causing the server to shutdown.

            Show
            jplindst Jan Lindström added a comment - commit f5ddffd83e627cc0f6a24dfe4d8fc2e0c983bf78 Author: Jan Lindström <jan.lindstrom@mariadb.com> Date: Thu Jun 18 19:58:57 2015 +0300 MDEV-8156 : Assertion failure in file log0crypt.cc line 220 on server restart Instead of asserting print informative error message to error log and return failure from innodb_init causing the server to shutdown.
            Hide
            Aurelien_LEQUOY Aurélien LEQUOY added a comment - - edited

            I just tried with lastest 10.1.6 (donwload and compiled 1 hour ago) and i got same problem !

            [mariadb-10.1]
            plugin-load-add=file_key_management.so
            file-key-management
            file-key-management
            file-key-management-filename='key.enc'
            file_key_management_filekey='secretPassword2'
            innodb-encrypt-tables
            innodb-encrypt-log
            innodb-encryption-threads=2
            encrypt-tmp-disk-tables=1
            

            create a table with encrypt
            insert one line

            remove these options and restart server and i got :

            150806 16:26:41 mysqld_safe Starting mysqld daemon with databases from /data/mysql/data
            2015-08-06 16:26:42 139969101432640 [Note] /usr/local/mysql/bin/mysqld (mysqld 10.1.6-MariaDB-log) starting as process 30296 ...
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Using mutexes to ref count buffer pool pages
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: The InnoDB memory heap is disabled
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Memory barrier is not used
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Compressed tables use zlib 1.2.3.4
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Not using CPU crc32 instructions
            2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Initializing buffer pool, size = 4.0G
            2015-08-06 16:26:43 139969101432640 [Note] InnoDB: Completed initialization of buffer pool
            2015-08-06 16:26:45 139969101432640 [Note] InnoDB: Highest supported file format is Barracuda.
            2015-08-06 16:26:45 139969101432640 [ERROR] InnoDB: Redo log crypto: getting mysqld crypto key from key version failed. Reason could b
            e that requested key_version 1 is not found or required encryption  key management is not found.
            2015-08-06 16:26:45 139969101432640 [ERROR] Plugin 'InnoDB' init function returned error.
            2015-08-06 16:26:45 139969101432640 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
            2015-08-06 16:26:45 139969101432640 [Note] Plugin 'FEEDBACK' is disabled.
            2015-08-06 16:26:45 139969101432640 [ERROR] Unknown/unsupported storage engine: InnoDB
            2015-08-06 16:26:45 139969101432640 [ERROR] Aborting
            
            2015-08-06 16:26:45 139969101432640 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete
            
            Show
            Aurelien_LEQUOY Aurélien LEQUOY added a comment - - edited I just tried with lastest 10.1.6 (donwload and compiled 1 hour ago) and i got same problem ! [mariadb-10.1] plugin-load-add=file_key_management.so file-key-management file-key-management file-key-management-filename='key.enc' file_key_management_filekey='secretPassword2' innodb-encrypt-tables innodb-encrypt-log innodb-encryption-threads=2 encrypt-tmp-disk-tables=1 create a table with encrypt insert one line remove these options and restart server and i got : 150806 16:26:41 mysqld_safe Starting mysqld daemon with databases from /data/mysql/data 2015-08-06 16:26:42 139969101432640 [Note] /usr/local/mysql/bin/mysqld (mysqld 10.1.6-MariaDB-log) starting as process 30296 ... 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Using mutexes to ref count buffer pool pages 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: The InnoDB memory heap is disabled 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Memory barrier is not used 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Compressed tables use zlib 1.2.3.4 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Not using CPU crc32 instructions 2015-08-06 16:26:42 139969101432640 [Note] InnoDB: Initializing buffer pool, size = 4.0G 2015-08-06 16:26:43 139969101432640 [Note] InnoDB: Completed initialization of buffer pool 2015-08-06 16:26:45 139969101432640 [Note] InnoDB: Highest supported file format is Barracuda. 2015-08-06 16:26:45 139969101432640 [ERROR] InnoDB: Redo log crypto: getting mysqld crypto key from key version failed. Reason could b e that requested key_version 1 is not found or required encryption key management is not found. 2015-08-06 16:26:45 139969101432640 [ERROR] Plugin 'InnoDB' init function returned error. 2015-08-06 16:26:45 139969101432640 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 2015-08-06 16:26:45 139969101432640 [Note] Plugin 'FEEDBACK' is disabled. 2015-08-06 16:26:45 139969101432640 [ERROR] Unknown/unsupported storage engine: InnoDB 2015-08-06 16:26:45 139969101432640 [ERROR] Aborting 2015-08-06 16:26:45 139969101432640 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete
            Hide
            jplindst Jan Lindström added a comment -

            Hi,

            To me this does not look the same. In original bug report there was a error message and crash. Now server refuses the start and prints error message (if full error log is provided). If requested key_version is not found there is no way to continue.

            Show
            jplindst Jan Lindström added a comment - Hi, To me this does not look the same. In original bug report there was a error message and crash. Now server refuses the start and prints error message (if full error log is provided). If requested key_version is not found there is no way to continue.
            Hide
            Aurelien_LEQUOY Aurélien LEQUOY added a comment -

            yes, but my point of view it's you miss key, so you lost encripted data => normal.

            But in this case you lost all data even data not encripted. (i just cripted one table one this table).

            More how to get back without encryption ?

            Show
            Aurelien_LEQUOY Aurélien LEQUOY added a comment - yes, but my point of view it's you miss key, so you lost encripted data => normal. But in this case you lost all data even data not encripted. (i just cripted one table one this table). More how to get back without encryption ?
            Hide
            jplindst Jan Lindström added a comment -

            Yes, can you explain step by step what you did, but original problem was that you had innodb-encrypt-log=on
            , after this log file is encrypted and if you lost the key you can't restart the database from latest checkpoint (because it is encrypted).

            Show
            jplindst Jan Lindström added a comment - Yes, can you explain step by step what you did, but original problem was that you had innodb-encrypt-log=on , after this log file is encrypted and if you lost the key you can't restart the database from latest checkpoint (because it is encrypted).

              People

              • Assignee:
                jplindst Jan Lindström
                Reporter:
                elenst Elena Stepanova
              • Votes:
                0 Vote for this issue
                Watchers:
                3 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 - 4 hours
                  4h

                    Agile