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

Crash recovery failure after the server is killed during innodb_encrypt_log startup

Details

    Description

      basic tests work, but e.g. if I force checkpoint in xb_file_key_management test by restarting Server right before backup:

      --source include/restart_mysqld.inc

      Then backup operation

      exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir

      will not be able parse logs ( note 'aborted at' is bigger than 'recovery from' ):

      2017-07-13 16:24:34 139729790940992 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1637690
      2017-07-13 16:24:34 139729790940992 [ERROR] InnoDB: Incorrect log record type:73
      2017-07-13 16:24:34 139729790940992 [Warning] InnoDB: Log scan aborted at LSN 1637376
      2017-07-13 16:24:34 139729790940992 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
      xtrabackup: innodb_init() returned 11 (Generic error).
      

      Full log:

      bash-4.2$ ./mtr xb_file_key_management
      Logging: ./mtr  xb_file_key_management
      vardir: /home/a/spd/_depot/m-tar/10.2.7/mysql-test/var
      Checking leftover processes...
      Removing old var directory...
      Creating var directory '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var'...
      Checking supported features...
      MariaDB Version 10.2.7-MariaDB
       - SSL connections supported
      Collecting tests...
      Installing system database...
       
      ==============================================================================
       
      TEST                                      RESULT   TIME (ms) or COMMENT
      --------------------------------------------------------------------------
       
      worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
      mariabackup.xb_file_key_management       [ fail ]
              Test ended at 2017-07-13 16:26:36
       
      CURRENT_TEST: mariabackup.xb_file_key_management
      mysqltest: At line 26: exec of '/home/a/spd/_depot/m-tar/10.2.7/bin/mariabackup  --prepare --target-dir=/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/tmp/backup 2>&1' failed, error: 256, status: 1, errno: 11
      Output from before failure:
      /home/a/spd/_depot/m-tar/10.2.7/bin/mariabackup based on MariaDB server 10.2.7-MariaDB Linux (x86_64) 
      xtrabackup: cd to /home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/tmp/backup/
      Loading encryption plugin
               Encryption plugin parameter :  '--file_key_management_encryption_algorithm=aes_cbc'
               Encryption plugin parameter :  '--file_key_management_filekey=FILE:/home/a/spd/_depot/m-tar/10.2.7/mysql-test/suite/mariabackup/filekeys-data.key'
               Encryption plugin parameter :  '--file_key_management_filename=/home/a/spd/_depot/m-tar/10.2.7/mysql-test/suite/mariabackup/filekeys-data.enc'
               Encryption plugin parameter :  '--prepare'
               Encryption plugin parameter :  '--target-dir=/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/tmp/backup'
      xtrabackup: This target seems to be not prepared yet.
      xtrabackup: using the following InnoDB configuration for recovery:
      xtrabackup:   innodb_data_home_dir = .
      xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
      xtrabackup:   innodb_log_group_home_dir = .
      xtrabackup: Starting InnoDB instance for recovery.
      xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Uses event mutexes
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Compressed tables use zlib 1.2.3
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Number of pools: 1
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Using SSE2 crc32 instructions
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Completed initialization of buffer pool
      2017-07-13 16:26:35 140655682647808 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Highest supported file format is Barracuda.
      2017-07-13 16:26:35 140656125790016 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1637690
      2017-07-13 16:26:35 140656125790016 [ERROR] InnoDB: Incorrect log record type:104
      2017-07-13 16:26:35 140656125790016 [Warning] InnoDB: Log scan aborted at LSN 1637376
      2017-07-13 16:26:35 140656125790016 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
      xtrabackup: innodb_init() returned 11 (Generic error).
       
       
       
      The result from queries just before the failure was:
      CREATE TABLE t(c VARCHAR(10)) ENGINE INNODB encrypted=yes;
      INSERT INTO t VALUES('foobar1');
      # xtrabackup backup
      NOT FOUND /foobar1/ in ib_logfile0
      # expect NOT FOUND
      INSERT INTO t VALUES('foobar2');
      # xtrabackup prepare
       
       - saving '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/log/mariabackup.xb_file_key_management/' to '/home/a/spd/_depot/m-tar/10.2.7/mysql-test/var/log/mariabackup.xb_file_key_management/'
      --------------------------------------------------------------------------
      The servers were restarted 0 times
      Spent 0.000 of 8 seconds executing testcases
       
      Failure: Failed 1/1 tests, 0.00% were successful.
       
      Failing test(s): mariabackup.xb_file_key_management
       
      The log files in var/log may give you some hint of what went wrong.
       
      If you want to report this error, please read first the documentation
      at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
       
      mysql-test-run: *** ERROR: there were failing test cases
      

      Attachments

        Issue Links

          Activity

            anikitin Andrii Nikitin (Inactive) created issue -

            LSN=1637690 rounded down to a multiple of 512 is LSN 1637376. This (together with the invalid redo log record type 71) means that Mariabackup was unable to read the encrypted redo log file.

            Where exactly was the line

            --source include/restart_mysqld.inc
            

            added? Please post an exact patch.

            marko Marko Mäkelä added a comment - LSN=1637690 rounded down to a multiple of 512 is LSN 1637376. This (together with the invalid redo log record type 71) means that Mariabackup was unable to read the encrypted redo log file. Where exactly was the line --source include/restart_mysqld.inc added? Please post an exact patch.
            marko Marko Mäkelä made changes -
            Field Original Value New Value
            Assignee Marko Mäkelä [ marko ] Andrii Nikitin [ anikitin ]

            Sorry - I wanted to verify in current tree and it somehow escaped my queue.

            Exact patch:

            diff --git a/mysql-test/suite/mariabackup/xb_file_key_management.test b/mysql-test/suite/mariabackup/xb_file_key_management.test
            index 3887a88..1a969f5 100644
            --- a/mysql-test/suite/mariabackup/xb_file_key_management.test
            +++ b/mysql-test/suite/mariabackup/xb_file_key_management.test
            @@ -6,6 +6,7 @@ INSERT INTO t VALUES('foobar1');
             echo # xtrabackup backup;
             let $targetdir=$MYSQLTEST_VARDIR/tmp/backup;
             --disable_result_log
            +--source include/restart_mysqld.inc
             exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf --backup --target-dir=$targetdir;
             --enable_result_log
            

            I've checked 10.2.8 fails similar way:

            mysqltest: At line 23: exec of '/home/a/mariadb-environs/_depot/m-tar/10.2.8/bin/mariabackup  --prepare --target-dir=/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/var/tmp/backup 2>&1' failed, error: 256, status: 1, errno: 11
            Output from before failure:
            /home/a/mariadb-environs/_depot/m-tar/10.2.8/bin/mariabackup based on MariaDB server 10.2.8-MariaDB Linux (x86_64) 
            xtrabackup: cd to /home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/var/tmp/backup/
            Loading encryption plugin
            	 Encryption plugin parameter :  '--file_key_management_encryption_algorithm=aes_cbc'
            	 Encryption plugin parameter :  '--file_key_management_filekey=FILE:/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/suite/mariabackup/filekeys-data.key'
            	 Encryption plugin parameter :  '--file_key_management_filename=/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/suite/mariabackup/filekeys-data.enc'
            	 Encryption plugin parameter :  '--prepare'
            	 Encryption plugin parameter :  '--target-dir=/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/var/tmp/backup'
            xtrabackup: This target seems to be not prepared yet.
            xtrabackup: using the following InnoDB configuration for recovery:
            xtrabackup:   innodb_data_home_dir = .
            xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
            xtrabackup:   innodb_log_group_home_dir = .
            xtrabackup: Starting InnoDB instance for recovery.
            xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Uses event mutexes
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Compressed tables use zlib 1.2.3
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Number of pools: 1
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Using SSE2 crc32 instructions
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Completed initialization of buffer pool
            2017-09-11  8:42:08 140484638906112 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Highest supported file format is Barracuda.
            2017-09-11  8:42:08 140484947158528 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1637690
            2017-09-11  8:42:08 140484947158528 [ERROR] InnoDB: Incorrect log record type:78
            2017-09-11  8:42:08 140484947158528 [Warning] InnoDB: Log scan aborted at LSN 1637376
            2017-09-11  8:42:08 140484947158528 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
            xtrabackup: innodb_init() returned 11 (Generic error).
            

            Current 10.2 tree fails little differently: backup succeeds, just InnoDB cannot start after restore:

            mysqltest: At line 29: query 'SELECT * FROM t' failed: 1286: Unknown storage engine 'InnoDB'
            

            With original error in Server log:

            2017-09-11  8:50:19 139838501836608 [Note] /home/a/mariadb-environs/m1-10.2/build/sql/mysqld (mysqld 10.2.9-MariaDB-log) starting as process 26091 ...
            2017-09-11  8:50:19 139838501836608 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
            2017-09-11  8:50:19 139838501836608 [Note] Plugin 'SEQUENCE' is disabled.
            2017-09-11  8:50:19 139838501836608 [Note] Plugin 'partition' is disabled.
            2017-09-11  8:50:19 139838501836608 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Uses event mutexes
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Compressed tables use zlib 1.2.8
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Using Linux native AIO
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Number of pools: 1
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Using SSE2 crc32 instructions
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Completed initialization of buffer pool
            2017-09-11  8:50:19 139838246328064 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Highest supported file format is Barracuda.
            2017-09-11  8:50:19 139838501836608 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1637178
            2017-09-11  8:50:19 139838501836608 [ERROR] InnoDB: Incorrect log record type:40
            2017-09-11  8:50:19 139838501836608 [Warning] InnoDB: Log scan aborted at LSN 1636864
            2017-09-11  8:50:19 139838501836608 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
            2017-09-11  8:50:20 139838501836608 [Note] InnoDB: Starting shutdown...
            2017-09-11  8:50:20 139838501836608 [ERROR] Plugin 'InnoDB' init function returned error.
            2017-09-11  8:50:20 139838501836608 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
            

            anikitin Andrii Nikitin (Inactive) added a comment - Sorry - I wanted to verify in current tree and it somehow escaped my queue. Exact patch: diff --git a /mysql-test/suite/mariabackup/xb_file_key_management . test b /mysql-test/suite/mariabackup/xb_file_key_management . test index 3887a88..1a969f5 100644 --- a /mysql-test/suite/mariabackup/xb_file_key_management . test +++ b /mysql-test/suite/mariabackup/xb_file_key_management . test @@ -6,6 +6,7 @@ INSERT INTO t VALUES( 'foobar1' ); echo # xtrabackup backup; let $targetdir=$MYSQLTEST_VARDIR /tmp/backup ; --disable_result_log +-- source include /restart_mysqld .inc exec $XTRABACKUP --defaults- file =$MYSQLTEST_VARDIR /my .cnf --backup --target- dir =$targetdir; --enable_result_log I've checked 10.2.8 fails similar way: mysqltest: At line 23: exec of '/home/a/mariadb-environs/_depot/m-tar/10.2.8/bin/mariabackup --prepare --target-dir=/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/var/tmp/backup 2>&1' failed, error: 256, status: 1, errno: 11 Output from before failure: /home/a/mariadb-environs/_depot/m-tar/10.2.8/bin/mariabackup based on MariaDB server 10.2.8-MariaDB Linux (x86_64) xtrabackup: cd to /home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/var/tmp/backup/ Loading encryption plugin Encryption plugin parameter : '--file_key_management_encryption_algorithm=aes_cbc' Encryption plugin parameter : '--file_key_management_filekey=FILE:/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/suite/mariabackup/filekeys-data.key' Encryption plugin parameter : '--file_key_management_filename=/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/suite/mariabackup/filekeys-data.enc' Encryption plugin parameter : '--prepare' Encryption plugin parameter : '--target-dir=/home/a/mariadb-environs/_depot/m-tar/10.2.8/mysql-test/var/tmp/backup' xtrabackup: This target seems to be not prepared yet. xtrabackup: using the following InnoDB configuration for recovery: xtrabackup: innodb_data_home_dir = . xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend xtrabackup: innodb_log_group_home_dir = . xtrabackup: Starting InnoDB instance for recovery. xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter) 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Uses event mutexes 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Compressed tables use zlib 1.2.3 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Number of pools: 1 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Using SSE2 crc32 instructions 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Completed initialization of buffer pool 2017-09-11 8:42:08 140484638906112 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Highest supported file format is Barracuda. 2017-09-11 8:42:08 140484947158528 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1637690 2017-09-11 8:42:08 140484947158528 [ERROR] InnoDB: Incorrect log record type:78 2017-09-11 8:42:08 140484947158528 [Warning] InnoDB: Log scan aborted at LSN 1637376 2017-09-11 8:42:08 140484947158528 [ERROR] InnoDB: Plugin initialization aborted with error Generic error xtrabackup: innodb_init() returned 11 (Generic error). Current 10.2 tree fails little differently: backup succeeds, just InnoDB cannot start after restore: mysqltest: At line 29: query 'SELECT * FROM t' failed: 1286: Unknown storage engine 'InnoDB' With original error in Server log: 2017-09-11 8:50:19 139838501836608 [Note] /home/a/mariadb-environs/m1-10.2/build/sql/mysqld (mysqld 10.2.9-MariaDB-log) starting as process 26091 ... 2017-09-11 8:50:19 139838501836608 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162) 2017-09-11 8:50:19 139838501836608 [Note] Plugin 'SEQUENCE' is disabled. 2017-09-11 8:50:19 139838501836608 [Note] Plugin 'partition' is disabled. 2017-09-11 8:50:19 139838501836608 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Uses event mutexes 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Compressed tables use zlib 1.2.8 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Using Linux native AIO 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Number of pools: 1 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Using SSE2 crc32 instructions 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Completed initialization of buffer pool 2017-09-11 8:50:19 139838246328064 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Highest supported file format is Barracuda. 2017-09-11 8:50:19 139838501836608 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1637178 2017-09-11 8:50:19 139838501836608 [ERROR] InnoDB: Incorrect log record type:40 2017-09-11 8:50:19 139838501836608 [Warning] InnoDB: Log scan aborted at LSN 1636864 2017-09-11 8:50:19 139838501836608 [ERROR] InnoDB: Plugin initialization aborted with error Generic error 2017-09-11 8:50:20 139838501836608 [Note] InnoDB: Starting shutdown... 2017-09-11 8:50:20 139838501836608 [ERROR] Plugin 'InnoDB' init function returned error. 2017-09-11 8:50:20 139838501836608 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
            anikitin Andrii Nikitin (Inactive) made changes -
            Assignee Andrii Nikitin [ anikitin ] Marko Mäkelä [ marko ]

            10.1 still isn't affected.
            10.3 fails to start identically after restore:

            2017-09-11  9:24:50 0 [Note] /home/a/mariadb-environs/m9-10.3/build/sql/mysqld (mysqld 10.3.2-MariaDB-log) starting as process 17721 ...
            2017-09-11  9:24:50 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
            2017-09-11  9:24:50 0 [Note] Plugin 'partition' is disabled.
            2017-09-11  9:24:50 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            2017-09-11  9:24:50 0 [Note] InnoDB: Uses event mutexes
            2017-09-11  9:24:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
            2017-09-11  9:24:50 0 [Note] InnoDB: Using Linux native AIO
            2017-09-11  9:24:50 0 [Note] InnoDB: Number of pools: 1
            2017-09-11  9:24:50 0 [Note] InnoDB: Using SSE2 crc32 instructions
            2017-09-11  9:24:50 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
            2017-09-11  9:24:50 0 [Note] InnoDB: Completed initialization of buffer pool
            2017-09-11  9:24:50 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2017-09-11  9:24:50 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1636966
            2017-09-11  9:24:50 0 [ERROR] InnoDB: Incorrect log record type:93
            2017-09-11  9:24:50 0 [Warning] InnoDB: Log scan aborted at LSN 1636864
            2017-09-11  9:24:50 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
            2017-09-11  9:24:50 0 [Note] InnoDB: Starting shutdown...
            2017-09-11  9:24:50 0 [ERROR] Plugin 'InnoDB' init function returned error.
            2017-09-11  9:24:50 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
            

            anikitin Andrii Nikitin (Inactive) added a comment - 10.1 still isn't affected. 10.3 fails to start identically after restore: 2017-09-11 9:24:50 0 [Note] /home/a/mariadb-environs/m9-10.3/build/sql/mysqld (mysqld 10.3.2-MariaDB-log) starting as process 17721 ... 2017-09-11 9:24:50 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162) 2017-09-11 9:24:50 0 [Note] Plugin 'partition' is disabled. 2017-09-11 9:24:50 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2017-09-11 9:24:50 0 [Note] InnoDB: Uses event mutexes 2017-09-11 9:24:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.8 2017-09-11 9:24:50 0 [Note] InnoDB: Using Linux native AIO 2017-09-11 9:24:50 0 [Note] InnoDB: Number of pools: 1 2017-09-11 9:24:50 0 [Note] InnoDB: Using SSE2 crc32 instructions 2017-09-11 9:24:50 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M 2017-09-11 9:24:50 0 [Note] InnoDB: Completed initialization of buffer pool 2017-09-11 9:24:50 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2017-09-11 9:24:50 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1636966 2017-09-11 9:24:50 0 [ERROR] InnoDB: Incorrect log record type:93 2017-09-11 9:24:50 0 [Warning] InnoDB: Log scan aborted at LSN 1636864 2017-09-11 9:24:50 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error 2017-09-11 9:24:50 0 [Note] InnoDB: Starting shutdown... 2017-09-11 9:24:50 0 [ERROR] Plugin 'InnoDB' init function returned error. 2017-09-11 9:24:50 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
            anikitin Andrii Nikitin (Inactive) made changes -
            Affects Version/s 10.2.8 [ 22544 ]
            Affects Version/s 10.3 [ 22126 ]
            anikitin Andrii Nikitin (Inactive) made changes -
            Fix Version/s 10.3 [ 22126 ]

            This is a bug that was introduced in MDEV-11782.
            It looks like innodb_encrypt_log might not be fully crash-safe.

            The function log_crypt() was computing the initialization vector incorrectly. A log write that comprises multiple redo log would derive the initialization vector for every block from the same LSN. Recovery or backup cannot know how many blocks were written per request. Maybe most writes actually are performed one 512-byte redo log block at a time?

            In this modified test, apparently there is only one redo log block that needs to be decrypted. Mariabackup --prepare is using the wrong initialization vector, because its log-scanning logic slightly differs from the normal server startup.

            This bug should not only affect backup, but also the crash recovery from MariaDB 10.2.4 or later when using innodb_encrypt_log=ON.

            marko Marko Mäkelä added a comment - This is a bug that was introduced in MDEV-11782 . It looks like innodb_encrypt_log might not be fully crash-safe. The function log_crypt() was computing the initialization vector incorrectly. A log write that comprises multiple redo log would derive the initialization vector for every block from the same LSN. Recovery or backup cannot know how many blocks were written per request. Maybe most writes actually are performed one 512-byte redo log block at a time? In this modified test, apparently there is only one redo log block that needs to be decrypted. Mariabackup --prepare is using the wrong initialization vector, because its log-scanning logic slightly differs from the normal server startup. This bug should not only affect backup, but also the crash recovery from MariaDB 10.2.4 or later when using innodb_encrypt_log=ON.
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            Affects Version/s 10.3.0 [ 22127 ]
            Affects Version/s 10.2.4 [ 22116 ]
            Affects Version/s 10.3 [ 22126 ]
            Affects Version/s 10.2.7 [ 22543 ]
            Affects Version/s 10.2.8 [ 22544 ]
            marko Marko Mäkelä made changes -
            Status Open [ 1 ] Confirmed [ 10101 ]
            marko Marko Mäkelä made changes -
            Status Confirmed [ 10101 ] In Progress [ 3 ]

            The bug that I suspected to have been introduced in MDEV-11782 actually pre-exists in the 10.1 server. To experience that bug, you would seem to need a server crash and recovery around the time when the most significant 32 bits of log_sys->lsn are changing, so that the most significant bits of log_block_get_start_lsn() would be wrong. Not very likely.

            The problem at hand seems to be unique to Mariabackup. I am still debugging it.

            marko Marko Mäkelä added a comment - The bug that I suspected to have been introduced in MDEV-11782 actually pre-exists in the 10.1 server. To experience that bug, you would seem to need a server crash and recovery around the time when the most significant 32 bits of log_sys->lsn are changing, so that the most significant bits of log_block_get_start_lsn() would be wrong. Not very likely. The problem at hand seems to be unique to Mariabackup. I am still debugging it.

            Starting with MariaDB 10.2.2, log_write_up_to() introduces the variable pad_size. The unused pad_size bytes would be encrypted as well, wasting CPU. I think that it is cleanest to invoke log_crypt() directly from log_write_up_to(), on the actual payload bytes.

            marko Marko Mäkelä added a comment - Starting with MariaDB 10.2.2, log_write_up_to() introduces the variable pad_size. The unused pad_size bytes would be encrypted as well, wasting CPU. I think that it is cleanest to invoke log_crypt() directly from log_write_up_to(), on the actual payload bytes.

            The test case revealed several problems:

            • a glitch in the way how log_crypt() converts LSN to initialization vector, and the most significant 32 bits of the LSN are about to change
            • lack of input validation in Mariabackup 10.2 (data_len in xtrabackup_copy_log() was out of range)
            • inherently unsafe redo log rekeying at server startup; crash recovery would fail before the first log checkpoint. To hide this problem, InnoDB startup used to do an extra redo log checkpoint, but luckily this test case was quick enough to invoke xtrabackup before the checkpoint had been completed.

            MDEV-12041 has been filed to properly implement redo log encryption key rotation. Until then, we must not call log_crypt_init() except when creating new redo log files.

            marko Marko Mäkelä added a comment - The test case revealed several problems: a glitch in the way how log_crypt() converts LSN to initialization vector, and the most significant 32 bits of the LSN are about to change lack of input validation in Mariabackup 10.2 (data_len in xtrabackup_copy_log() was out of range) inherently unsafe redo log rekeying at server startup; crash recovery would fail before the first log checkpoint. To hide this problem, InnoDB startup used to do an extra redo log checkpoint, but luckily this test case was quick enough to invoke xtrabackup before the checkpoint had been completed. MDEV-12041 has been filed to properly implement redo log encryption key rotation. Until then, we must not call log_crypt_init() except when creating new redo log files.
            marko Marko Mäkelä made changes -
            Summary mariabackup with innodb-encrypt-log=ON may show 'Incorrect log record type' Crash recovery failure after the server is killed during innodb_encrypt_log startup
            marko Marko Mäkelä made changes -
            Assignee Marko Mäkelä [ marko ] Jan Lindström [ jplindst ]
            Status In Progress [ 3 ] In Review [ 10002 ]
            marko Marko Mäkelä made changes -
            Affects Version/s 10.1.3 [ 18000 ]

            I believe that many of these problems exist in the MariaDB 10.1 impelmentation of innodb_encrypt_log. Backporting the fix would be nontrivial, because the redo log encryption code was significantly cleaned up by MDEV-11782 in 10.2.4.
            The extra checkpoint in innobase_start_or_create_for_mysql() was added in MariaDB 10.1.5 as part of MDEV-8041.

            marko Marko Mäkelä added a comment - I believe that many of these problems exist in the MariaDB 10.1 impelmentation of innodb_encrypt_log. Backporting the fix would be nontrivial, because the redo log encryption code was significantly cleaned up by MDEV-11782 in 10.2.4. The extra checkpoint in innobase_start_or_create_for_mysql() was added in MariaDB 10.1.5 as part of MDEV-8041 .
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -

            ok to push.

            jplindst Jan Lindström (Inactive) added a comment - ok to push.
            jplindst Jan Lindström (Inactive) made changes -
            Assignee Jan Lindström [ jplindst ] Marko Mäkelä [ marko ]
            Status In Review [ 10002 ] Stalled [ 10000 ]
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            issue.field.resolutiondate 2017-09-12 08:38:26.0 2017-09-12 08:38:26.655
            marko Marko Mäkelä made changes -
            Fix Version/s 10.2.9 [ 22611 ]
            Fix Version/s 10.3.2 [ 22533 ]
            Fix Version/s 10.2 [ 14601 ]
            Fix Version/s 10.3 [ 22126 ]
            Resolution Fixed [ 1 ]
            Status Stalled [ 10000 ] Closed [ 6 ]
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            serg Sergei Golubchik made changes -
            Workflow MariaDB v3 [ 81663 ] MariaDB v4 [ 152483 ]

            People

              marko Marko Mäkelä
              anikitin Andrii Nikitin (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              4 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.