apply-log fails with error log seq number is in future

[Percona]

./innobackup-1.5.1 --apply-log /var/lib/mysql/backup/2009-03-06_17-06-17/

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy.
All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

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

innobackup:: Warning: Ignored unrecognized line 1 in options : './xtrabackup Ver alpha-0.2 for 5.0.77 unknown-linux-gnu (x86_64)
'

090306 19:51:58 innobackup: Starting ibbackup with command: ./xtrabackup --prepare --target-dir=/var/lib/mysql/backup/2009-03-06_17-06-17

./xtrabackup Ver alpha-0.2 for 5.0.77 unknown-linux-gnu (x86_64)
xtrabackup_logfile detected: size=4177920, start_lsn=(53 2203680185)
InnoDB: Log scan progressed past the checkpoint lsn 53 2203680185
090306 19:51:58 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 53 2206675456
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 0 457053440
090306 19:52:00 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 090306 19:52:00 InnoDB: Error: page 5698 log sequence number 53 2206837124
InnoDB: is in the future! Current system log sequence number 53 2206675233.
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.0/en/forcing-recovery.html
InnoDB: for more information.
090306 19:52:00 InnoDB: Error: page 5730 log sequence number 53 2206720672
InnoDB: is in the future! Current system log sequence number 53 2206675233.
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.0/en/forcing-recovery.html
InnoDB: for more information.

[Percona (percona-team)]

Here is log from backup

./innobackup-1.5.1 /var/lib/mysql/backup/

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy.
All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackup
           prints "innobackup completed OK!".

innobackup: Using mysql Ver 14.12 Distrib 5.0.67, for redhat-linux-gnu (x86_64) using readline 5.1
innobackup: Using mysql server version 5.0.67-percona-b7-log

innobackup:: Warning: Ignored unrecognized line 1 in options : './xtrabackup Ver alpha-0.2 for 5.0.77 unknown-linux-gnu (x86_64)
'
innobackup: Created backup directory /var/lib/mysql/backup/2009-03-06_17-06-17
090306 17:06:17 innobackup: Starting mysql with options: --unbuffered
090306 17:06:17 innobackup: Connected to database with mysql child process (pid=3084)
090306 17:06:21 innobackup: Connection to database server closed

090306 17:06:21 innobackup: Starting ibbackup with command: ./xtrabackup --backup --suspend-at-end --target-dir=/var/lib/mysql/backup/2009-03-06_17-06-17
innobackup: Waiting for ibbackup (pid=3094) to suspend
innobackup: Suspend file '/var/lib/mysql/backup/2009-03-06_17-06-17/xtrabackup_suspended'

./xtrabackup Ver alpha-0.2 for 5.0.77 unknown-linux-gnu (x86_64)
>> log scanned up to (53 2204070829)
Copying ./ibdata1
     to /var/lib/mysql/backup/2009-03-06_17-06-17/ibdata1
        ...done

..........

innobackup: Backing up files '/var/lib/mysql/st/*.{frm,MYD,MYI,MRG,TRG,TRN,opt}' (159 files)
>> log scanned up to (53 2207846582)
>> log scanned up to (53 2207846582)
>> log scanned up to (53 2207846582)
>> log scanned up to (53 2207846582)
090306 17:21:50 innobackup: Finished backing up .frm, .MRG, .MYD, .MYI, .TRG, .TRN, and .opt files

innobackup: Resuming ibbackup

Stopping log copying thread.>> log scanned up to (53 2207846582)

Transaction log of lsn (53 2203680185) to (53 2207846582) was copied.
090306 17:21:55 innobackup: All tables unlocked
090306 17:21:55 innobackup: Connection to database server closed

innobackup: Backup created in directory '/var/lib/mysql/backup/2009-03-06_17-06-17'
innobackup: MySQL binlog position: filename 'mysql-bin.000020', position 530
090306 17:21:55 innobackup: innobackup completed OK!

[Yasufumi Kinoshita (yasufumi-kinoshita)]

Thank you.

We should suppress the InnoDB error messages when "--prepare".
Please ignore them for now,

[MarkD (mark-davis-ewetel)]

Hello,

if i --prepare my backup, i get the following errors:

# ./xtrabackup --prepare
./xtrabackup Ver beta-0.4 for 5.1.32 unknown-linux-gnu (x86_64)
xtrabackup_logfile detected: size=231063552, start_lsn=(23 1769429644)
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Log scan progressed past the checkpoint lsn 23 1769429644
090402 11:01:12 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer..
InnoDB: Doing recovery: scanned up to log sequence number 23 1774672384 (2 %)
InnoDB: Doing recovery: scanned up to log sequence number 23 1779915264 (4 %)
....
InnoDB: Doing recovery: scanned up to log sequence number 23 2000116224 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 23 2000474712 (99 %)
090402 11:28:39 InnoDB: ERROR: We were only able to scan the log up to 23 2000474712
InnoDB: but a database page a had an lsn 23 2137052144. It is possible that the
InnoDB: database is now corrupt!
090402 11:28:39 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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: Last MySQL binlog file position 0 16569046, file name /mysql/logs/rad-db1.002794
090402 11:29:25 InnoDB: Started; log sequence number 23 2000474712

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 16569046, file name /mysql/logs/rad-db1.002794

090402 11:29:25 InnoDB: Starting shutdown...
090402 11:29:27 InnoDB: Assertion failure in thread 1171810624 in file btr/btr0pcur.c line 402
InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_frame_get_page_no(page)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
Aborted

Is this related to this bugreport or something completly different? I did not check, if this backup is functional or not.

Greets
Mark

[Vadim Tkachenko (vadim-tk)]

MarkD,

This is valid bug, and we hope we fixed it in latest Launchpad commit,
can you get new version from there ?

MarkD wrote:
> Hello,
>
> if i --prepare my backup, i get the following errors:
>
> # ./xtrabackup --prepare
> ./xtrabackup Ver beta-0.4 for 5.1.32 unknown-linux-gnu (x86_64)
> xtrabackup_logfile detected: size=231063552, start_lsn=(23 1769429644)
> xtrabackup: Starting InnoDB instance for recovery.
> xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
> InnoDB: Log scan progressed past the checkpoint lsn 23 1769429644
> 090402 11:01:12 InnoDB: Database was not shut down normally!
> InnoDB: Starting crash recovery.
> InnoDB: Reading tablespace information from the .ibd files...
> InnoDB: Restoring possible half-written data pages from the doublewrite
> InnoDB: buffer..
> InnoDB: Doing recovery: scanned up to log sequence number 23 1774672384 (2 %)
> InnoDB: Doing recovery: scanned up to log sequence number 23 1779915264 (4 %)
> ....
> InnoDB: Doing recovery: scanned up to log sequence number 23 2000116224 (99 %)
> InnoDB: Doing recovery: scanned up to log sequence number 23 2000474712 (99 %)
> 090402 11:28:39 InnoDB: ERROR: We were only able to scan the log up to 23 2000474712
> InnoDB: but a database page a had an lsn 23 2137052144. It is possible that the
> InnoDB: database is now corrupt!
> 090402 11:28:39 InnoDB: Starting an apply batch of log records to the database...
> InnoDB: Progress in percents: 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: Last MySQL binlog file position 0 16569046, file name /mysql/logs/rad-db1.002794
> 090402 11:29:25 InnoDB: Started; log sequence number 23 2000474712
>
> [notice (again)]
> If you use binary log and don't use any hack of group commit,
> the binary log position seems to be:
> InnoDB: Last MySQL binlog file position 0 16569046, file name /mysql/logs/rad-db1.002794
>
> 090402 11:29:25 InnoDB: Starting shutdown...
> 090402 11:29:27 InnoDB: Assertion failure in thread 1171810624 in file btr/btr0pcur.c line 402
> InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_frame_get_page_no(page)
> InnoDB: We intentionally generate a memory trap.
> InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
> InnoDB: If you get repeated assertion failures or crashes, even
> InnoDB: immediately after the mysqld startup, there may be
> InnoDB: corruption in the InnoDB tablespace. Please refer to
> InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
> InnoDB: about forcing recovery.
> Aborted
>
> Is this related to this bugreport or something completly different? I
> did not check, if this backup is functional or not.
>
> Greets
> Mark
>

--
Vadim Tkachenko, CTO
Percon...

[MarkD (mark-davis-ewetel)]

HI Vadim,

just got the latest revno. 34 from launchpad. Began from scratch (extract, patch, build).

# /home/md/xtrabackup --backup
./xtrabackup Ver beta-0.4 for 5.1.32 unknown-linux-gnu (x86_64)
>> log scanned up to (25 733862973)
Copying //mysql/data/ibdata1
     to /mysql/backup/ibdata1
>> log scanned up to (25 734293011)
>> log scanned up to (25 734619380)
        ...done
>> log scanned up to (25 734971958)
...
The latest check point (for incremental): '25:579639574'
>> log scanned up to (25 769313172)
Stopping log copying thread.
Transaction log of lsn (25 543693125) to (25 769313172) was copied.

Now the --prepare directly fails at start:

# ./xtrabackup --prepare
./xtrabackup Ver beta-0.4 for 5.1.32 unknown-linux-gnu (x86_64)
xtrabackup: This target seems to be not prepared yet.
xtrabackup_logfile detected: size=225624064, start_lsn=(25 543693125)
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
090403 9:48:58 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
InnoDB: File name .//mysql/data/ibdata1
InnoDB: File operation call: 'create'.
InnoDB: Cannot continue operation.

My innodb/xtrabackup config:

innodb_data_file_path = /mysql/data/ibdata1:128M:autoextend
innodb_file_per_table
innodb_log_group_home_dir = /mysql/logs
innodb_buffer_pool_size = 4096M
innodb_additional_mem_pool_size = 32M
innodb_log_file_size = 128M
innodb_log_files_in_group = 2
innodb_log_buffer_size = 16M
innodb_flush_log_at_trx_commit = 2
innodb_lock_wait_timeout = 50
innodb_thread_concurrency = 0

[xtrabackup]
target_dir = /mysql/backup

[Percona (percona-team)]

MarkD,

It seems something wrong with directory parsing.

Can you try

./xtrabackup --prepare --target-dir=/mysql/backup ?

[MarkD (mark-davis-ewetel)]

Mh, the xtrabackup_logfile seems to be gone after the first --prepare try. I did a new backup and tried directly with --target-dir=/mysql/backup

Transaction log of lsn (26 3355645360) to (26 3571411070) was copied.
# ./xtrabackup --prepare --target-dir=/mysql/backup
./xtrabackup Ver beta-0.4 for 5.1.32 unknown-linux-gnu (x86_64)
xtrabackup: This target seems to be not prepared yet.
xtrabackup_logfile detected: size=215777280, start_lsn=(26 3355645360)
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
090404 8:34:07 InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
InnoDB: If you are installing InnoDB, remember that you must create
InnoDB: directories yourself, InnoDB does not create them.
InnoDB: File name .//mysql/data/ibdata1
InnoDB: File operation call: 'create'.
InnoDB: Cannot continue operation.

The same result. And the xtrabackup_logfile gets deleted after the "--prepare".

xtrabackup_logfile detected: size=215777280, start_lsn=(26 3355645360)

looks like he finds the directory, but something else seems to be broken. .//mysql/data/ibdata1 isn't right. This looks more _like_ the source directory (without .) .

[Yasufumi Kinoshita (yasufumi-kinoshita)]

I may have fixed your case.
Thank you.

http://bazaar.launchpad.net/~percona-dev/percona-xtrabackup/trunk/revision/35

[MarkD (mark-davis-ewetel)]

Hi,

just recompiled (rev 36) with mysql-5.1.33. --backup and --prepare work as expected now.

Thx,

greets
Mark

[Shahriyar Rzayev (rzayev-sehriyar)]

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