Problem during --apply-log

[Percona]

backup was finished with next information:

>> log scanned up to (1317 3505471428)
Transaction log of lsn (1317 1513697222) to (1317 3505471428) was copied.
090331 16:30:11 innobackupex: All tables unlocked
090331 16:30:11 innobackupex: Connection to database server closed

innobackupex: Backup created in directory '/mnt/data/tmp'
innobackupex: MySQL binlog position: filename 'db02-bin.001263', position 1031512296
090331 16:34:21 innobackupex: innobackup completed OK!
innobackupex: You must use -i (--ignore-zeros) option for extraction of the tar stream.

Now I run --apply-log:

innobackupex-1.5.1 --use-memory=1G --apply-log /mnt/data/db

and after some period of time getting error:

InnoDB: Doing recovery: scanned up to log sequence number 1317 2043227648 (26 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2048470528 (26 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2053713408 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2058956288 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2064199168 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2067140096 (27 %)
090331 17:54:23 InnoDB: ERROR: We were only able to scan the log up to 1317 2067140096
InnoDB: but a database page a had an lsn 1317 3480803499. It is possible that the
InnoDB: database is now corrupt!
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 4 row operations to undo
InnoDB: Trx id counter is 4 86778112
090331 17:54:23 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 3570942, file name ./db02-bin.001262
InnoDB: Starting in background the rollback of uncommitted transactions
090331 18:11:09 InnoDB: Rolling back trx with id 4 86777617, 4 rows to undo
090331 18:11:09 InnoDB: Started; log sequence number 1317 2067140018

[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 3570942, file name ./db02-bin.001262

090331 18:11:09 InnoDB: Starting shutdown...
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933cd5; asc I < ;; 1: len 8; hex 000000007917bd3d; asc y =;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933b07; asc I ; ;; 1: len 8; hex 000000007916f43d; asc y =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK , undo log entries 3

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933ebd; asc I > ;; 1: len 8; hex 000000007918193d; asc y =;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933d6e; asc I =n;; 1: len 8; hex 000000007916f03d; asc y =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK , undo log entries 2

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933bf0; asc I ; ;; 1: len 8; hex 000000007918353d; asc y 5=;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933b07; asc I ; ;; 1: len 8; hex 000000007916f43d; asc y =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK , undo log entries 1

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933f0b; asc I ? ;; 1: len 8; hex 0000000079182c3d; asc y ,=;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933d6e; asc I =n;; 1: len 8; hex 000000007916f03d; asc y =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK

InnoDB: Submit a detailed bug report to http://bugs.mysql.com

InnoDB: Rolling back of trx id 4 86777617 completed
090331 18:11:09 InnoDB: Rollback of non-prepared transactions completed

and process seems hung there.

[Percona (percona-team)]

For reference backup was taken on one server to different as:
db06: nc -l 7000 | tar -xivf -
db02: ./innobackupex-1.5.1 --stream=tar /mnt/data/tmp/ | nc db06 7000

[Percona (percona-team)]

After fix it works better, but I still see unclear messages:

InnoDB: Doing recovery: scanned up to log sequence number 1318 1142470656 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1147713536 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1152956416 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1158199296 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1163442176 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1168685056 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1172160781 (99 %)
InnoDB: ##########################################################
InnoDB: WARNING!
InnoDB: The log sequence number in ibdata files is higher
InnoDB: than the log sequence number in the ib_logfiles! Are you sure
InnoDB: you are using the right ib_logfiles to start up the database?
InnoDB: Log sequence number in ib_logfiles is 1317 3806902419, log
InnoDB: sequence numbers stamped to ibdata file headers are between
InnoDB: 1318 1213947916 and 1318 1213947916.
InnoDB: ##########################################################
090402 13:30:43 InnoDB: ERROR: We were only able to scan the log up to 1318 1172160781
InnoDB: but a database page a had an lsn 1318 1213947739. It is possible that the
InnoDB: database is now corrupt!
090402 13:30:43 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 165363629, file name ./db02-bin.001266
090402 14:09:59 InnoDB: Started; log sequence number 1318 1172160781
InnoDB: Last MySQL binlog file position 0 165363629, file name ./db02-bin.001266
090402 14:09:59 InnoDB: Starting shutdown...
090402 14:10:01 InnoDB: Shutdown completed; log sequence number 1318 1172160781
xtrabackup Ver beta-0.4 for 5.0.77 unknown-linux-gnu (x86_64)
xtrabackup_logfile detected: size=1660239872, start_lsn=(1317 3806902419)

[Percona (percona-team)]

In additional to previous report, backup was taken as

>> log scanned up to (1318 1172160781)
Transaction log of lsn (1317 3806902419) to (1318 1172160781) was copied.
090402 00:14:42 innobackupex: All tables unlocked
090402 00:14:42 innobackupex: Connection to database server closed

innobackupex: Backup created in directory '/mnt/data/tmp'
innobackupex: MySQL binlog position: filename 'db02-bin.001266', position 165363629
090402 00:15:24 innobackupex: innobackup completed OK!
innobackupex: You must use -i (--ignore-zeros) option for extraction of the tar stream.

So it seems 1318 1172160781 is really last record in log.

[Yasufumi Kinoshita (yasufumi-kinoshita)]

Sorry, the older version seems to have problem still.
Your xtrabackup may access another datafiles at innodb_data_home_dir (not at target-dir).
I think it has been fixed at least at the newest revision.
http://bazaar.launchpad.net/~percona-dev/percona-xtrabackup/trunk/revision/34

Sorry, again. Please try again....

[Vadim Tkachenko (vadim-tk)]

I still see

InnoDB: Doing recovery: scanned up to log sequence number 1319 810647552 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1319 813701532 (99 %)
090404 12:24:41 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 090404 12:24:42 InnoDB: ERROR: the age of the last checkpoint is 2073991665,
InnoDB: which exceeds the log group capacity 1866599424.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
090404 12:24:58 InnoDB: ERROR: the age of the last checkpoint is 2074001439,
InnoDB: which exceeds the log group capacity 1866599424.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
0 090404 12:25:20 InnoDB: ERROR: the age of the last checkpoint is 2074015762,
InnoDB: which exceeds the log group capacity 1866599424.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
1 090404 12:25:38 InnoDB: ERROR: the age of the last checkpoint is 2074019901,

Backup was taken as:

The latest check point (for incremental): '1319:813219999'
>> log scanned up to (1319 813701532)
Transaction log of lsn (1318 3034677302) to (1319 813701532) was copied.
090404 06:03:29 innobackupex: All tables unlocked
090404 06:03:29 innobackupex: Connection to database server closed

innobackupex: Backup created in directory '/mnt/data/tmp'
innobackupex: MySQL binlog position: filename 'db02-bin.001271', position 247627478
090404 06:07:58 innobackupex: innobackup completed OK!
innobackupex: You must use -i (--ignore-zeros) option for extraction of the tar stream.

[Yasufumi Kinoshita (yasufumi-kinoshita)]

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

I have fixed except for,
"
InnoDB: Doing recovery: scanned up to log sequence number 1319 813701532 (99 %)
090405 4:29:47 InnoDB: ERROR: We were only able to scan the log up to 1319 813701532
InnoDB: but a database page a had an lsn 1319 814039859. It is possible that the
InnoDB: database is now corrupt!
"

It may need to investigate more.

The progress of log is come from process of insert-buffer.
And the precessed page's LSN becomes newer.
And the page may be "re-read" during the recovery...
(I don't know why "re-read" the same page yet....)

[Yasufumi Kinoshita (yasufumi-kinoshita)]

The last remained error message may be,,,,
http://bugs.mysql.com/bug.php?id=44140

The fix have been pushed
http://bazaar.launchpad.net/~percona-dev/percona-xtrabackup/trunk/revision/39

[Yasufumi Kinoshita (yasufumi-kinoshita)]

With the newer than revision 39, the message
"
InnoDB: Doing recovery: scanned up to log sequence number 1319 813701532 (99 %)
090405 4:29:47 InnoDB: ERROR: We were only able to scan the log up to 1319 813701532
InnoDB: but a database page a had an lsn 1319 814039859. It is possible that the
InnoDB: database is now corrupt!
"
is cause by "partial re-prepare". (situation of some files are already prepared)
I think the message may not appear at normal situation now.

[Shahriyar Rzayev (rzayev-sehriyar)]

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