Server reports InnoDB: Error: page <nr> log sequence number <nr> InnoDB: is in the future! Current system log sequence number <nr>. on first start after archive logs applied.

[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.
- Copy all full ib_log_archive files 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
- Delete server data dir, recreate and run: innobackupex --defaults-file=$PWD/mysql.1/my.cnf --copy-back $PWD/backup-0.0
- Start server...
2013-06-27 16:29:43 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-06-27 16:29:43 22085 [Warning] You need to use --log-bin to make --binlog-format work.
2013-06-27 16:29:43 22085 [Note] Plugin 'FEDERATED' is disabled.
2013-06-27 16:29:43 22085 [Note] InnoDB: The InnoDB memory heap is disabled
2013-06-27 16:29:43 22085 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-06-27 16:29:43 22085 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-06-27 16:29:43 22085 [Note] InnoDB: Using Linux native AIO
2013-06-27 16:29:43 22085 [Note] InnoDB: Not using CPU crc32 instructions
2013-06-27 16:29:43 22085 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2013-06-27 16:29:43 22085 [Note] InnoDB: Completed initialization of buffer pool
2013-06-27 16:29:43 22085 [Note] InnoDB: Highest supported file format is Barracuda.
2013-06-27 16:29:43 22085 [Warning] InnoDB: The log sequence number in the ibdata files is higher than the log sequence number in the ib_logfiles! Are you sure you are using the right ib_logfiles to start up the database. Log sequence number in the ib_logfiles i
s 44864012, logsequence numbers stamped to ibdata file headers are between 94325231 and 94325231.
2013-06-27 16:29:43 22085 [Note] InnoDB: The log sequence numbers 94325231 and 94325231 in ibdata files do not match the log sequence number 44864012 in the ib_logfiles!
2013-06-27 16:29:43 22085 [Note] InnoDB: Database was not shutdown normally!
2013-06-27 16:29:43 22085 [Note] InnoDB: Starting crash recovery.
2013-06-27 16:29:43 22085 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-06-27 16:29:43 22085 [Note] InnoDB: Restoring possible half-written data pages
2013-06-27 16:29:43 22085 [Note] InnoDB: from the doublewrite buffer...
2013-06-27 16:29:43 7fc3e49c0720 InnoDB: Error: page 7 log sequence number 66252945
InnoDB: is in the future! Current system log sequence number 44864012.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2013-06-27 16:29:43 7fc3e49c0720 InnoDB: Error: page 1 log sequence number 48683291
InnoDB: is in the future! Current system log sequence number 44864012.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2013-06-27 16:29:43 7fc3e49c0720 InnoDB: Error: page 3 log sequence number 48683291
InnoDB: is in the future! Current system log sequence number 44864012.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
...this goes on for several hundred times

When the server is ready, all expected data seems there and server _seems_ OK, but these kinds of errors coming off what s supposed to be a fresh restore are concerning.

[George Ormond Lorch III (gl-az)]

More info:
When trying something out for Vlad, I noticed that I am getting these errors on the first restore in my test cycle. This means that there were no archive logs involved. I tried the following test without innodb_log_archive enabled:

innobackupex --defaults-file=$PWD/mysql.1/my.cnf --no-timestamp --tmpdir=$PWD $PWD/backup-0.0
xtrabackup --defaults-file=$PWD/mysql.1/my.cnf --prepare --target-dir=$PWD/backup-0.0
     InnoDB: Shutdown completed; log sequence number 82159141
rm -rf $PWD/mysql.1/data; mkdir $PWD/mysql.1/data
innobackupex --defaults-file=$PWD/mysql.1/my.cnf --copy-back $PWD/backup-0.0
start server:
2013-07-01 16:46:28 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-07-01 16:46:28 13627 [Warning] You need to use --log-bin to make --binlog-format work.
2013-07-01 16:46:28 13627 [Note] Plugin 'FEDERATED' is disabled.
2013-07-01 16:46:28 13627 [Note] InnoDB: The InnoDB memory heap is disabled
2013-07-01 16:46:28 13627 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-07-01 16:46:28 13627 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-07-01 16:46:28 13627 [Note] InnoDB: Using Linux native AIO
2013-07-01 16:46:28 13627 [Note] InnoDB: Not using CPU crc32 instructions
2013-07-01 16:46:28 13627 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2013-07-01 16:46:28 13627 [Note] InnoDB: Completed initialization of buffer pool
2013-07-01 16:46:28 13627 [Note] InnoDB: Setting log file ./ib_logfile101 size to 256 MB
InnoDB: Progress in MB: 100 200
2013-07-01 16:46:28 13627 [Note] InnoDB: Setting log file ./ib_logfile1 size to 256 MB
InnoDB: Progress in MB: 100 200
2013-07-01 16:46:29 13627 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2013-07-01 16:46:29 13627 [Warning] InnoDB: New log files created, LSN=82159141
2013-07-01 16:46:29 13627 [Note] InnoDB: Highest supported file format is Barracuda.
2013-07-01 16:46:29 7f22d9d28720 InnoDB: Error: page 195 log sequence number 82159641
InnoDB: is in the future! Current system log sequence number 82159628.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2013-07-01 16:46:29 7f22d9d28720 InnoDB: Error: page 466 log sequence number 82159641
InnoDB: is in the future! Current system log sequence number 82159628.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
... on and on ...

[Vlad Lesin (vlad-lesin)]

George, could you specify please what versions of XB and PS this bug affects?

[George Ormond Lorch III (gl-az)]

Vlad, I ran into this with XB 2.1 from
~vlad-lesin/percona-xtrabackup/2.1-apply-archived-logs-innodb5.6:
------------------------------------------------------------
revno: 610
committer: Vlad Lesin <email address hidden>
branch nick: percona-xtrabackup-2.1-arch-log
timestamp: Thu 2013-06-27 21:00:06 +0400
message:

and PS 5.6 trunk from a week ago or so:
------------------------------------------------------------
revno: 389 [merge]
committer: Laurynas Biveinis <email address hidden>
branch nick: 5.6
timestamp: Fri 2013-06-21 12:02:58 +0300
message:
   Automerge lp:~stewart/percona-server/bug1072573-5.6

On 7/2/2013 4:01 AM, Vlad Lesin wrote:
> George, could you specify please what versions of XB and PS this bug
> affects?
>
> ** Changed in: percona-xtrabackup/2.1
> Assignee: Vlad Lesin (vlad-lesin) => (unassigned)
>

--
George O. Lorch III
Software Engineer, Percona
[phone] x542 US/Arizona (GMT -7)
skype: george.ormond.lorch.iii

[Alexey Kopytov (akopytov)]

George,

If you can repeat this issue, can you also provide full backup + prepare log and the contents of xtrabackup_checkpoints?

[George Ormond Lorch III (gl-az)]

Here is the transcript with innobackupex/xtrabackup output, my.cnf, xtrabackup_checkpoints and server log. This is or was pretty easy to reproduce via PTB. If necessary I can create a simple script that reproduces it and give you access to the environment.