innobackupex --apply-log fails with The transaction log file is corrupted

Dear support,

I am running percona server 5.6.24-72.2-log, innobackupex 2.3.3 Linux (x86_64).

A full backup is created using the following command:

innobackupex --default-file=/path/to/my/defaults/file.cnf --user=myuser --password=mypasswd --no-timestamp /my/path/to/backup/timestamp | tee -a /my/path/to/log/file.log

(…)
160125 19:34:45 Finished backing up non-InnoDB tables and files
160125 19:34:45 Executing LOCK BINLOG FOR BACKUP…
160125 19:34:45 [00] Writing xtrabackup_binlog_info
160125 19:34:45 [00] …done
160125 19:34:45 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS…
xtrabackup: The latest check point (for incremental): ‘2980804563434’
xtrabackup: Stopping log copying thread.
.160125 19:34:45 >> log scanned up to (2980804563434)
(…)
160125 19:34:45 Executing UNLOCK BINLOG
160125 19:34:45 Executing UNLOCK TABLES
160125 19:34:45 All tables unlocked
160125 19:34:45 Backup created in directory ‘/data2//20160125_181155’
MySQL binlog position: filename ‘mysql-bin-log.000016’, position ‘120’
160125 19:34:45 [00] Writing backup-my.cnf
160125 19:34:45 [00] …done
160125 19:34:45 [00] Writing xtrabackup_info
160125 19:34:45 [00] …done
xtrabackup: Transaction log of lsn (2980804563434) to (2980804563434) was copied.
160125 19:34:45 completed OK!

Takes 82 minutes.

Then I prepare this backup using:

$ /home/products/xtrabackup/bin/innobackupex --use-memory=1G --apply-log /my/path/to/backup/timestamp | tee -a /my/path/to/prepare/log/file.log

160126 10:57:47 innobackupex: Starting the apply-log operation

IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints “completed OK!”.

/home/products/xtrabackup/bin/innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
xtrabackup: cd to /data2/20160125_181155
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(2980804563434)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 1073741824 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file ./ibdata1 did not exist: a new database to be created!
InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait…
InnoDB: Setting log file ./ib_logfile101 size to 2 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=45781
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: 1 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 0

xtrabackup: error: The transaction log file is corrupted.
xtrabackup: error: The log was not applied to the intended LSN!
xtrabackup: Log applied to lsn 0
xtrabackup: The intended lsn is 2980804563434

Interestingly the xtrabackup_logfile file has been deleted from the backup path. If I save the xtrabackup_logfile before running the prepare, and restore it after, the first prepare crashes with transaction log corrupted, the next try to prepare works:

$ cp /tmp/xtrabackup_logfile /my/path/to/backup/timestamp/

# Run the prepare again:
$ /home/products/xtrabackup/bin/innobackupex --use-memory=1G --apply-log /my/path/to/backup/timestamp/ | tee -a /my/path/to/prepare/log/file.log
160126 10:58:21 innobackupex: Starting the apply-log operation

IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints “completed OK!”.

/home/products/xtrabackup/bin/innobackupex version 2.3.3 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 525ca7d)
xtrabackup: cd to /data2/20160125_181155
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(2980804563434)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 1073741824 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: The log sequence numbers 0 and 0 in ibdata files do not match the log sequence number 2980804563434 in the ib_logfiles!
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer…
InnoDB: 1 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 2980804563434

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown…
InnoDB: Shutdown completed; log sequence number 2980804563444
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 1.0G
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 48 MB
InnoDB: Setting log file ./ib_logfile1 size to 48 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=2980804563444
InnoDB: Highest supported file format is Barracuda.
InnoDB: 1 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.24 started; log sequence number 2980804563468
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown…
InnoDB: Shutdown completed; log sequence number 2980804563478
160126 10:58:41 completed OK!

I have no problem in 2.1.8. I am going to test in 2.2. I looked into the forum posts and I didn’t find a match. Could it be a bug on 2.3.3 ?

Thanks,