Percona XtraBackup moved to https://jira.percona.com/projects/PXB

Archive logs --prepare after --apply-logs-only gives error InnoDB: Archive log file <nr> starts from too big a lsn

Bug #1199555 reported by George Ormond Lorch III
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Triaged
Medium
Vlad Lesin
Percona XtraBackup moved to https://jira.percona.com/projects/PXB future-2.3-releases
2.1
Triaged
Medium
Vlad Lesin
Percona XtraBackup moved to https://jira.percona.com/projects/PXB future-2.1-releases
2.2
Triaged
Medium
Vlad Lesin
Percona XtraBackup moved to https://jira.percona.com/projects/PXB future-2.2-releases
2.3
Triaged
Medium
Vlad Lesin
Percona XtraBackup moved to https://jira.percona.com/projects/PXB future-2.3-releases

Bug Description

This may not be a supported use of archive logs and if not I think we should report something when preparing archive logs and we notice --apply-logs-only also specified and document usage accordingly _or_ maybe this is a valid use case in which there is an issue as described below:

Using XB 2.1 from ~vlad-lesin/percona-xtrabackup/2.1-apply-archived-logs-innodb5.6:
------------------------------------------------------------
revno: 611
committer: Vlad Lesin <email address hidden>
branch nick: percona-xtrabackup-2.1-arch-log
timestamp: Thu 2013-07-04 13:43:59 +0400
message:
  Use PS-5.6.11 for testing xtradb56 engine as PS-5.6.11 supports logs archiving.

and PS 5.6 trunk from a few weeks ago:
------------------------------------------------------------
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

So the setup with basic sysbench oltp write only load on the server:
Take a basic full backup into $PWD/backup-0.0
Wait a bit and move all but current archive logs into $PWD/backup-0.1
> ls -la $PWD/backup-0.1
-rw-rw----. 1 root root 67108864 Jul 9 22:41 ib_log_archive_00000000000000045568
-rw-rw----. 1 root root 67108864 Jul 9 22:42 ib_log_archive_00000000000067152384
-rw-rw----. 1 root root 67108864 Jul 9 22:42 ib_log_archive_00000000000134259200
Wait a bit more and again move all but current archive logs into $PWD/backup-0.2
> ls -la $PWD/backup-0.2
-rw-r-----. 1 root root 67108864 Jul 9 22:52 ib_log_archive_00000000000134259200

> cp -r $PWD/backup-0.0 $PWD/restore-base
> cp -r $PWD/backup-0.1 $PWD/restore-logs-0
> cp -r $PWD/backup-0.2 $PWD/restore-logs-1

Run first prepare:
> ( PATH=/mnt/bin/ps-5.6/bin:/mnt/bin/ps-5.6/libexec:/mnt/bin/xb-2.1-xtradb56-log-archive:$PATH; xtrabackup --defaults-file=$PWD/mysql.1/my.cnf --prepare --apply-logs-only --target-dir=$PWD/restore-base --innodb-log-arch-dir=$PWD/restore-logs-0 )

xtrabackup version 2.1.3 for MySQL server 5.6.10 Linux (x86_64) (revision id: undefined)
xtrabackup: cd to /mnt/test/var/test-0/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 = 67108864
InnoDB: Allocated tablespace 2, old maximum was 0
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 = 67108864
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 64 MB
InnoDB: Setting log file ./ib_logfile1 size to 64 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=44859916
InnoDB: Starting archive recovery from a backup...
InnoDB: Allocated tablespace 2, old maximum was 0
InnoDB: Opened archived log file /mnt/test/var/test-0/restore-logs-0/ib_log_archive_00000000000000045568
InnoDB: Opened archived log file /mnt/test/var/test-0/restore-logs-0/ib_log_archive_00000000000067152384
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: 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: 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 19 row operations to undo
InnoDB: Trx id counter is 63744

[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: Shutdown completed; log sequence number 134259030

Now run the next prepare:
> ( PATH=/mnt/bin/ps-5.6/bin:/mnt/bin/ps-5.6/libexec:/mnt/bin/xb-2.1-xtradb56-log-archive:$PATH; xtrabackup --defaults-file=$PWD/mysql.1/my.cnf --prepare --target-dir=$PWD/restore-base --innodb-log-arch-dir=$PWD/restore-logs-1 )

xtrabackup version 2.1.3 for MySQL server 5.6.10 Linux (x86_64) (revision id: undefined)
xtrabackup: cd to /mnt/test/var/test-0/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 = 67108864
InnoDB: Allocated tablespace 2, old maximum was 0
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 = 67108864
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: Starting archive recovery from a backup...
InnoDB: Allocated tablespace 2, old maximum was 0
InnoDB: Opened archived log file /mnt/test/var/test-0/restore-logs-1/ib_log_archive_00000000000134259200
InnoDB: Archive log file /mnt/test/var/test-0/restore-logs-1/ib_log_archive_00000000000134259200 starts from too big a lsn
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 19 row operations to undo
InnoDB: Trx id counter is 63744

[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: Shutdown completed; log sequence number 134259030

Alexey Kopytov (akopytov)
Changed in percona-xtrabackup:
assignee: nobody → Vlad Lesin (vlad-lesin)
milestone: none → 2.1.4
importance: Undecided → High
Revision history for this message
Vlad Lesin (vlad-lesin) wrote :

--apply-logs-only is mandatory for archived logs applying because it is assumed that unfinished transactions can be finished during the further logs applying. Even if this option is not set by user explicitly it is set in xtrabackup.cc implicitly:

                /*
                  Unfinished transactions are not rolled back during log applying
                  as they can be finished at the firther files applyings.
                */
                srv_apply_log_only = TRUE;

The bug is reproduced without --apply-logs-only too.

Revision history for this message
Vlad Lesin (vlad-lesin) wrote :

This is not a bug. The matter is one log record can be in two log files so the beginning of the record is in one and the ending is in another log file. When the first set of log files were applied the last log record was not applied as it was not read completely. So the last log file in the first log files set must be the first log file in the second set. The bug should be closed when this feature is documented.

Revision history for this message
George Ormond Lorch III (gl-az) wrote :

OK, based on IRC chats and retesting, this is not a bug as per Vlads comments but it is a documentation issue. If multiple -prepare --apply-log-only calls are made against a common base backup, the last ib_log_archive from the previous --prepare must be in the -innodb-log-arch-dir. For example, given the example above the contents of the directories must be:

> ls $PWD/backup-0.1
ib_log_archive_00000000000000045568
ib_log_archive_00000000000067152384

> ls -la $PWD/backup-0.2
ib_log_archive_00000000000067152384 << Note must be in both
ib_log_archive_00000000000134259200

Revision history for this message
Vlad Lesin (vlad-lesin) wrote :

I modified xb_apply_archived_logs.sh test so that it contains both --apply-log-only and --innodb-log-arch-dir options as well as the case of applying log by sets where the last log file in the previous set is the same as the first log file in the next set.

Revision history for this message
Alexey Kopytov (akopytov) wrote :

Can we fix the error message to be more descriptive on what steps should be done to avoid it?

tags: added: log-archiving
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.