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

              People

              • Assignee:
                marko Marko Mäkelä
                Reporter:
                anikitin Andrii Nikitin (Inactive)
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: