Failed to recover from full backup -> CORRUPT LOG RECORD FOUND

[Shahriyar Rzayev]

Testing branch -> https://github.com/gl-sergei/percona-xtrabackup/tree/2.4-xb-bug1555626

#### Running:
[root@ps-pxb-5 ~]# while true; do bash test.sh; done
[root@ps-pxb-5 ~]# cat test.sh
#!/bin/bash

echo "drop table if exists db1.sb1" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
echo "create table db1.sb1 as select id,c from db1.sbtest1 where id < 150000;"| mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
echo "alter table db1.sb1 encryption='Y'" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
echo "create unique index ix on db1.sb1 (id)" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
sleep 1
echo "drop table if exists db2.sb1" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
echo "create table db2.sb1 as select id,c from db2.sbtest1 where id < 150000;" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
echo "alter table db2.sb1 encryption='Y'" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock
echo "create unique index ix on db2.sb1 (id)" | mysql -u root -pBaku12345# --socket=/var/lib/mysql/mysql.sock

#### Taking backup

[root@ps-pxb-5 bin]# cat run_backup.sh
./xtrabackup --defaults-file=/etc/my.cnf --backup --target-dir=/home/backup_dir/full/ --datadir=/var/lib/mysql --user=root --password=Baku12345# --socket=/var/lib/mysql/mysql.sock --no-version-check --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

sleep 10

./xtrabackup --defaults-file=/etc/my.cnf --backup --target-dir=/home/backup_dir/inc/inc1 --incremental-basedir=/home/backup_dir/full/ --datadir=/var/lib/mysql --user=root --password=Baku12345# --socket=/var/lib/mysql/mysql.sock --no-version-check --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

sleep 10

./xtrabackup --defaults-file=/etc/my.cnf --backup --target-dir=/home/backup_dir/inc/inc2 --incremental-basedir=/home/backup_dir/inc/inc1 --datadir=/var/lib/mysql --user=root --password=Baku12345# --socket=/var/lib/mysql/mysql.sock --no-version-check --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

sleep 10

./xtrabackup --defaults-file=/etc/my.cnf --backup --target-dir=/home/backup_dir/inc/inc3 --incremental-basedir=/home/backup_dir/inc/inc2 --datadir=/var/lib/mysql --user=root --password=Baku12345# --socket=/var/lib/mysql/mysql.sock --no-version-check --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

#### Preparing backup

[root@ps-pxb-5 bin]# cat prepare_backup.sh
./xtrabackup --defaults-file=/home/backup_dir/full/backup-my.cnf --prepare --apply-log-only --target-dir=/home/backup_dir/full --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

sleep 10

./xtrabackup --defaults-file=/home/backup_dir/full/backup-my.cnf --prepare --apply-log-only --target-dir=/home/backup_dir/full --incremental-dir=/home/backup_dir/inc/inc1 --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

sleep 10

./xtrabackup --defaults-file=/home/backup_dir/full/backup-my.cnf --prepare --apply-log-only --target-dir=/home/backup_dir/full --incremental-dir=/home/backup_dir/inc/inc2 --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

sleep 10

./xtrabackup --defaults-file=/home/backup_dir/full/backup-my.cnf --prepare --target-dir=/home/backup_dir/full --incremental-dir=/home/backup_dir/inc/inc3 --keyring-file-data=/var/lib/mysql-keyring/keyring --server-id=0

Result:

InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 28656965990
InnoDB: Doing recovery: scanned up to log sequence number 28662208512 (4%)
InnoDB: Doing recovery: scanned up to log sequence number 28667451392 (8%)
InnoDB: Doing recovery: scanned up to log sequence number 28672694272 (12%)
InnoDB: Doing recovery: scanned up to log sequence number 28660897792 (3%)
InnoDB: Doing recovery: scanned up to log sequence number 28666140672 (7%)
InnoDB: Doing recovery: scanned up to log sequence number 28671383552 (11%)
InnoDB: Ignoring data file './db2/sb1.ibd' with space ID 1007, since the redo log references ./db2/sb1.ibd with space ID 1003.
InnoDB: Doing recovery: scanned up to log sequence number 28676626432 (15%)
InnoDB: Doing recovery: scanned up to log sequence number 28681869312 (19%)
InnoDB: Doing recovery: scanned up to log sequence number 28687112192 (23%)
InnoDB: Doing recovery: scanned up to log sequence number 28692355072 (27%)
InnoDB: Doing recovery: scanned up to log sequence number 28697597952 (31%)
InnoDB: Encryption can't find master key, please check the keyring plugin is loaded.
InnoDB: Encryption information in the redo log of space 1008 is invalid
InnoDB: ############### CORRUPT LOG RECORD FOUND ##################
InnoDB: Log record type 30, page 1008:0. Log parsing proceeded successfully up to 28702041009. Previous log record type 4, is multi 1 Recv offset 241501, prev 241494
InnoDB: Hex dump starting 100 bytes before and ending 100 bytes after the corrupted record:
 len 207; hex 0000aa010183f00000ae80fe0183f00000ae80fa0483f00000aa020483f0000052000283f0000056809e0483f0000058000283f000005c809e0483f000009ef0ffffffff0283f00000a2000483f00000a4f0ffffffff0283f00000a8000483f000004e010483f000003a021e83f000289600536c43410000000100000000a713eec65a9c5a22c60a79a17b461b20ef5634dce82c0d65a997e51c7e2546590bd4dd643b04a215de8de584c75b26aee783b23142ed2d378e28cfc94715cbc485a77d27000000001f080000006e000000; asc R V X \ N : ( SlCA Z Z" y {F V4 , e ~%FY d; [& 1B -7 ( G }' n ;
InnoDB: Set innodb_force_recovery to ignore this error.
InnoDB: Plugin initialization aborted at srv0start.cc[2206] with error Generic error
xtrabackup: innodb_init(): Error occured.

[Shahriyar Rzayev (rzayev-sehriyar)]

Testing Branch:
https://github.com/gl-sergei/percona-xtrabackup/tree/2.4-xb-re-encrypt

The result is similar so putting here as comment.

Creating, inserting, altering:

[root@ps-pxb-5 ~]# cat create_encrypted_tables.py
import mysql.connector

cnx = mysql.connector.connect(user='root', password='Baku12345#',
                              host='127.0.0.1',
                              database='dbtest2')
cursor = cnx.cursor()

create_stmt = "create table sbtest%s like dbtest.sbtest1"
insert_stmt = "insert into sbtest%s select * from dbtest.sbtest1 where id < 100"
alter_stmt = "alter table sbtest%s encryption='Y'"

for i in range(10000):
 cursor.execute(create_stmt % i)
 print "created table sbtest%s" % i
 cursor.execute(insert_stmt % i)
 print "Inserted into table sbtest%s" % i
 cursor.execute(alter_stmt % i)
 print "Ecnryption altered table sbtest%s" %i

cursor.close()
cnx.close()

Rotating master key:

[root@ps-pxb-5 ~]# cat alter_rotate_keyring.py
import mysql.connector

cnx = mysql.connector.connect(user='root', password='Baku12345#',
                              host='127.0.0.1',
                              database='dbtest')
cursor = cnx.cursor()

alter_stmt = "ALTER INSTANCE ROTATE INNODB MASTER KEY"

while(True):
 print "Master key rotated"
 cursor.execute(alter_stmt)

cursor.close()
cnx.close()

Result of prepare:

[root@ps-pxb-5 full]# /usr/local/xtrabackup/bin/xtrabackup --defaults-file=/home/backup_dir/full/backup-my.cnf --prepare --target-dir=/home/backup_dir/full
/usr/local/xtrabackup/bin/xtrabackup version 2.4.2 based on MySQL server 5.7.11 Linux (x86_64) (revision id: b43f6fb)
xtrabackup: cd to /home/backup_dir/full
xtrabackup: This target seems to be not prepared yet.
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=69074944, start_lsn=(1370234141)
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: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 69074944
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: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 69074944
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: PUNCH HOLE support available
InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.7
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
InnoDB: Completed initialization of buffer pool
InnoDB: page_cleaner coordinator priority: -20
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 13702341...

[Sergei Glushchenko (sergei.glushchenko)]

Original test case might not reproduce the same issue due to fix for #1582345
Is it possible to create a test case reproducing the same issue without "ALTER INSTANCE ROTATE INNODB MASTER KEY"?

[Shahriyar Rzayev (rzayev-sehriyar)]

Yes, after fix for #1582345 original test case is not reproducible.
For second test case without "ALTER INSTANCE ROTATE INNODB MASTER KEY" it is not reproducible too.

[Launchpad Janitor (janitor)]

[Expired for Percona XtraBackup 2.4 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-475