Archive log prepare reports 'InnoDB: Archive log file <nr> does not scan right' when using --to-archived-lsn

[George Ormond Lorch III]

Using PS 5.6 trunk (revno 389) and ~vlad-lesin/percona-xtrabackup/2.1-apply-archived-logs-innodb5.6 and temporary fix for bug 1195055.

Sequence is pretty simple:
- Start server with: --binlog-format=ROW --innodb_buffer_pool_size=1G --innodb_file_format=barracuda --innodb_file_per_table=1 --innodb_log_archive=1 --innodb_log_file_size=2M
- Start sysbench 100% write load, 2 threads, 16 tables and 10000 max rows per table
- Wait 5 seconds
- Take base backup with command: innobackupex --defaults-file=$PWD/mysql.1/my.cnf --no-timestamp --tmpdir=$PWD $PWD/backup-0.0
- Wait 10-20 seconds, enough time to get 15 or 20 ib_log_archive files.
- Capture current server lsn through "SHOW ENGINE INNODB STATUS", in this case it is 96004922
- Wait for a new ib_log_archive file to appear with starting lsn greater than captured lsn
- Copy all full ib_log_archive with starting lsn less than captured lsn to $PWD/backup-0.1
- Stop load and server.
- Prepare backup with command: xtrabackup --defaults-file=$PWD/mysql.1/my.cnf --prepare --target-dir=$PWD/backup-0.0 --innodb-log-arch-dir=$PWD/backup-0.1 --to-archived-lsn=96004922

xtrabackup version 2.1.3 for MySQL server 5.6.10 Linux (x86_64) (revision id: undefined)
xtrabackup: cd to /mnt/test/var/test-1/restore-base
xtrabackup: Temporary instance for recovery is set as followings.
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 = 2097152
xtrabackup: Temporary instance for recovery is set as followings.
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 = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: CPU does not support crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 2 MB
InnoDB: Setting log file ./ib_logfile1 size to 2 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=45138444
InnoDB: Starting archive recovery from a backup...
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000044042752
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000046137856
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000048232960
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000050328064
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000052423168
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000054518272
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000056613376
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000058708480
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000060803584
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000062898688
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000064993792
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000067088896
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000069184000
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000071279104
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000073374208
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000075469312
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000077564416
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000079659520
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000081754624
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000083849728
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000085944832
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000088039936
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000090135040
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000092230144
InnoDB: Opened archived log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000094325248
InnoDB: Archive log file /mnt/test/var/test-1/restore-logs/ib_log_archive_00000000000094325248 does not scan right
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 37120

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: Starting shutdown...
InnoDB: Log sequence number at shutdown 45138956 is lower than at startup 96005102!
InnoDB: Shutdown completed; log sequence number 45138956

The test validates fine and everything seems ok, but that could be a concerning note to a user.

[Vlad Lesin (vlad-lesin)]

Fixed in the last version of related branch. George, could you check it please?

[Alexey Kopytov (akopytov)]

Did not appear in any released versions. Should go to "other bugs" in release notes.

[Shahriyar Rzayev (rzayev-sehriyar)]

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