unable to restore due to wrong from_lsn referential

unable to restore due to wrong from_lsn referential when incremental backup is scheduled directy following fullbackup / differential backup

the incremental backup is refering to the lsn of the incremental backup taken before the the fullbackup. therefore the chain is broken and we cannot restore to a point in time after the full backup:

STEP 1

so i’m trying to restore a full backup with 1 incremental backup

in this case : restore
| 2,735 | F | 1,769 | 3,976,126,388 | 2017-07-22 22:05:03 | XXXXX-mysql-full-0552 |
| 2,736 | I | 2 | 13,599,028 | 2017-07-22 22:29:43 | XXXXX-mysql-inc-0238 |

*restore
Automatically selected Catalog: XXXXXtestCatalog
Using Catalog “XXXXXtestCatalog”

First you select one or more JobIds that contain files
to be restored. You will be presented several methods
of specifying the JobIds. Then you will be allowed to
select which files from those JobIds are to be restored.

To select the JobIds, you have the following choices:
1: List last 20 Jobs run
2: List Jobs where a given File is saved
3: Enter list of comma separated JobIds to select
4: Enter SQL list command
5: Select the most recent backup for a client
6: Select backup for a client before a specified time
7: Enter a list of files to restore
8: Enter a list of files to restore before a specified time
9: Find the JobIds of the most recent backup for a client
10: Find the JobIds for a backup for a client before a specified time
11: Enter a list of directories to restore for found JobIds
12: Select full restore to a specified Job date
13: Cancel
Select item: (1-13): 5
Defined Clients:
1: XXXXXdbscluster01
2: XXXXXtestbardir01
3: XXXXXtestbarsd01
4: XXXXXtestdc01
5: XXXXXtestsrv01
6: XXXXXtestvmon01
7: XXXXXtestws10
Select the Client (1-7): 1
The defined FileSet resources are:
1: XXXXX-mysql-fileset
2: ubuntu-standard-fileset
Select FileSet resource (1-2): 1
±------±------±---------±--------------±--------------------±---------------------+
| JobId | Level | JobFiles | JobBytes | StartTime | VolumeName |
±------±------±---------±--------------±--------------------±---------------------+
| 2,735 | F | 1,769 | 3,976,126,388 | 2017-07-22 22:05:03 | XXXXX-mysql-full-0552 |
| 2,736 | I | 2 | 13,599,028 | 2017-07-22 22:29:43 | XXXXX-mysql-inc-0238 |
| 2,738 | I | 2 | 14,546,614 | 2017-07-22 23:20:03 | XXXXX-mysql-inc-0239 |
| 2,746 | I | 2 | 48,484,089 | 2017-07-23 00:20:03 | XXXXX-mysql-inc-0240 |


±------±------±---------±--------------±--------------------±---------------------+
You have selected the following JobIds: 2735,2736,2738,2746,2747,2748,2749,2750,2751,2752,2753,2754,2755,2756,2757,2759,2760,2761,2762,2763

Building directory tree for JobId(s) 2735,2736,2738,2746,2747,2748,2749,2750,2751,2752,2753,2754,2755,2756,2757,2759,2760,2761,2762,2763 … +++++++++++++++++++++++++++++++++++++++++++++
1,644 files inserted into the tree.

You are now entering file selection mode where you add (mark) and
remove (unmark) files to be restored. No files are initially added, unless
you used the “all” keyword on the command line.
Enter “done” to leave this mode.

cwd is: /
$ cd _percona
cwd is: /_percona/
$ ls
xbstream.0000002735
xbstream.0000002736
xbstream.0000002738

$ mark xbstream.0000002735
1 file marked.
$ mark xbstream.0000002736
1 file marked.
$ done
Bootstrap records written to /var/lib/bareos/XXXXXtestbardir01-dir.restore.3.bsr

→ restore was succesfull

STEP 2: prepare and recover

→ the error occurs when trying to recover the incremental backup taken after the fullbackup

restore the fullbackup

xtrabackup --prepare --apply-log-only --target-dir=/mnt/sharedbackup/mysql/restore/_percona/2764/00000000000000000000_00000003805644266034_0000002735

xtrabackup version 2.4.7 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 6f7a799)
xtrabackup: cd to /mnt/sharedbackup/mysql/restore/_percona/2764/00000000000000000000_00000003805644266034_0000002735/
xtrabackup: This target seems to be not prepared yet.
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=8388608, start_lsn=(3805643872752)
xtrabackup: using the following InnoDB configuration for recovery:
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 = 1
xtrabackup: innodb_log_file_size = 8388608
xtrabackup: using the following InnoDB configuration for recovery:
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 = 1
xtrabackup: innodb_log_file_size = 8388608
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.3.4
InnoDB: Number of pools: 1
InnoDB: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
InnoDB: Completed initialization of buffer pool
InnoDB: page_cleaner coordinator priority: -20
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 3805643872752
InnoDB: Doing recovery: scanned up to log sequence number 3805644266034 (5%)
InnoDB: Doing recovery: scanned up to log sequence number 3805644266034 (5%)
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Doing recovery: scanned up to log sequence number 3805644266034 (5%)
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: xtrabackup: Last MySQL binlog file position 226516, file name /var/mysql_binlogs/XXXXXdbs06_mysql_bin_log.028078
InnoDB: page_cleaner: 1000ms intended loop took 49886ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
InnoDB: xtrabackup: Last MySQL binlog file position 226516, file name /var/mysql_binlogs/XXXXXdbs06_mysql_bin_log.028078

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: Starting shutdown…
InnoDB: Shutdown completed; log sequence number 3805644266043
InnoDB: Number of pools: 1
170723 17:37:14 completed OK!

restore the first incremental after fullbackup

xtrabackup --prepare --target-dir=/mnt/sharedbackup/mysql/restore/_percona/2764/00000000000000000000_00000003805644266034_0000002735 --incremental-dir=/mnt/sharedbackup/mysql/restore/_percona/2764/00000003805643369005_00000003805644499741_0000002736

root@XXXXXdbs06:/mnt/sharedbackup/mysql/restore/_percona/2764# xtrabackup --prepare --target-dir=/mnt/sharedbackup/mysql/restore/_percona/2764/00000000000000000000_00000003805644266034_0000002735 --incremental-dir=/mnt/sharedbackup/mysql/restore/_percona/2764/00000003805643369005_00000003805644499741_0000002736
xtrabackup version 2.4.7 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 6f7a799)
incremental backup from 3805643369005 is enabled.
xtrabackup: cd to /mnt/sharedbackup/mysql/restore/_percona/2764/00000000000000000000_00000003805644266034_0000002735/
xtrabackup: This target seems to be already prepared with --apply-log-only.
xtrabackup: error: This incremental backup seems not to be proper for the target.
xtrabackup: Check ‘to_lsn’ of the target and ‘from_lsn’ of the incremental.

→ this restore of the incremental backups hould refer to the lsn of the fullbackup of job 2735, but according to the bareos logs the incremental backup job 2736 is refering to the lsn of job 2734 (which means the job before the fullbackup)

→ in the bareos logs i do see that the incremental backup launched ater the fullbackup is refering to the lsn of the incremental backup taken just before the fullbackup :

→ see attachment : bareos.log

snippet from the bareos log :

→ job 2734 is the last incremental before the fullbackup

22-Jul 21:20 XXXXXtestbardir01-dir JobId 2734: Start Backup JobId 2734, Job=XXXXXdbscluster01-mysql-job.2017-07-22_21.20.00_42
22-Jul 21:20 XXXXXtestbardir01-dir JobId 2734: There are no more Jobs associated with Volume “XXXXX-mysql-inc-0236”. Marking it purged.
22-Jul 21:20 XXXXXtestbardir01-dir JobId 2734: All records pruned from Volume “XXXXX-mysql-inc-0236”; marking it “Purged”
22-Jul 21:20 XXXXXtestbardir01-dir JobId 2734: Recycled volume “XXXXX-mysql-inc-0236”
22-Jul 21:20 XXXXXtestbardir01-dir JobId 2734: Using Device “XXXXXtestDrive01” to write.
22-Jul 21:20 XXXXXdbs06 JobId 2734: python-fd: Got to_lsn 3805642413293 from restore object of job 2733
22-Jul 21:20 XXXXXtestbarsd01-sd JobId 2734: Recycled volume “XXXXX-mysql-inc-0236” on device “XXXXXtestDrive01” (/backup/file), all previous data lost.
22-Jul 21:20 XXXXXtestbardir01-dir JobId 2734: Max Volume jobs=1 exceeded. Marking Volume “XXXXX-mysql-inc-0236” as Used.
22-Jul 21:20 XXXXXdbs06 JobId 2734: python-fd: Starting backup of /_percona/xbstream.0000002734
22-Jul 21:34 XXXXXdbs06 JobId 2734: python-fd: Starting backup of /_percona/xtrabackup_checkpoints
22-Jul 21:34 XXXXXtestbarsd01-sd JobId 2734: Elapsed time=00:13:58, Transfer rate=16.09 K Bytes/second
22-Jul 21:34 XXXXXtestbardir01-dir JobId 2734: Bareos XXXXXtestbardir01-dir 16.2.5 (03Mar17):
Build OS: x86_64-pc-linux-gnu ubuntu Ubuntu 14.04.5 LTS
JobId: 2734
Job: XXXXXdbscluster01-mysql-job.2017-07-22_21.20.00_42
Backup Level: Incremental, since=2017-07-22 20:20:03
Client: “XXXXXdbscluster01” 16.2.4 (01Jul16) x86_64-pc-linux-gnu,ubuntu,Ubuntu 12.04 LTS,xUbuntu_12.04,x86_64
FileSet: “XXXXX-mysql-fileset” 2017-05-15 22:05:00
Pool: “XXXXX-mysql-inc-pool” (From Job IncPool override)
Catalog: “XXXXXtestCatalog” (From Client resource)
Storage: “XXXXXtestbarsd01-sd” (From Job resource)
Scheduled time: 22-Jul-2017 21:20:00
Start time: 22-Jul-2017 21:20:03
End time: 22-Jul-2017 21:34:01
Elapsed time: 13 mins 58 secs
Priority: 10
FD Files Written: 2
SD Files Written: 2
FD Bytes Written: 13,490,411 (13.49 MB)
SD Bytes Written: 13,490,973 (13.49 MB)
Rate: 16.1 KB/s
Software Compression: 87.7 % (gzip)
VSS: no
Encryption: no
Accurate: no
Volume name(s): XXXXX-mysql-inc-0236
Volume Session Id: 1006
Volume Session Time: 1498057792
Last Volume Bytes: 13,519,454 (13.51 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK

22-Jul 21:34 XXXXXtestbardir01-dir JobId 2734: shell command: run AfterJob “/var/XXXXX/scripts/nbs/bareos/nbs_log_result XXXXXdbscluster01 Incremental Backup 2734 XXXXXdbscluster01-my
sql-job OK”

→ the new fullbackup job
22-Jul 22:05 XXXXXtestbardir01-dir JobId 2735: Start Backup JobId 2735, Job=XXXXXdbscluster01-mysql-job.2017-07-22_22.05.00_43
22-Jul 22:05 XXXXXtestbardir01-dir JobId 2735: Recycled volume “XXXXX-mysql-full-0552”
22-Jul 22:05 XXXXXtestbardir01-dir JobId 2735: Using Device “XXXXXtestDrive01” to write.
22-Jul 22:05 XXXXXtestbarsd01-sd JobId 2735: Recycled volume “XXXXX-mysql-full-0552” on device “XXXXXtestDrive01” (/backup/file), all previous data lost.
22-Jul 22:05 XXXXXtestbardir01-dir JobId 2735: Max Volume jobs=1 exceeded. Marking Volume “XXXXX-mysql-full-0552” as Used.
22-Jul 22:05 XXXXXdbs06 JobId 2735: python-fd: Starting backup of /_percona/xbstream.0000002735
22-Jul 22:29 XXXXXdbs06 JobId 2735: python-fd: Starting backup of /_percona/xtrabackup_checkpoints
22-Jul 22:29 XXXXXtestbarsd01-sd JobId 2735: Elapsed time=00:24:37, Transfer rate=2.692 M Bytes/second
22-Jul 22:29 XXXXXtestbardir01-dir JobId 2735: Bareos XXXXXtestbardir01-dir 16.2.5 (03Mar17):
Build OS: x86_64-pc-linux-gnu ubuntu Ubuntu 14.04.5 LTS
JobId: 2735
Job: XXXXXdbscluster01-mysql-job.2017-07-22_22.05.00_43
Backup Level: Full
Client: “XXXXXdbscluster01” 16.2.4 (01Jul16) x86_64-pc-linux-gnu,ubuntu,Ubuntu 12.04 LTS,xUbuntu_12.04,x86_64
FileSet: “XXXXX-mysql-fileset” 2017-05-15 22:05:00
Pool: “XXXXX-mysql-full-pool” (From Job resource)
Catalog: “XXXXXtestCatalog” (From Client resource)
Storage: “XXXXXtestbarsd01-sd” (From Job resource)
Scheduled time: 22-Jul-2017 22:05:00
Start time: 22-Jul-2017 22:05:03
End time: 22-Jul-2017 22:29:40
Elapsed time: 24 mins 37 secs
Priority: 10
FD Files Written: 1,769
SD Files Written: 1,769
FD Bytes Written: 3,976,126,388 (3.976 GB)
SD Bytes Written: 3,976,338,584 (3.976 GB)
Rate: 2692.0 KB/s
Software Compression: 83.6 % (gzip)
VSS: no
Encryption: no
Accurate: no
Volume name(s): XXXXX-mysql-full-0552
Volume Session Id: 1007
Volume Session Time: 1498057792
Last Volume Bytes: 3,983,050,997 (3.983 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK

22-Jul 22:29 XXXXXtestbardir01-dir JobId 2735: shell command: run AfterJob “/var/XXXXX/scripts/nbs/bareos/nbs_log_result XXXXXdbscluster01 Full Backup 2735 XXXXXdbscluster01-mysql-job OK”

→ the first incremental after the fullbackup, the one that should refer to the lsn number of the fullbackup

22-Jul 22:29 XXXXXtestbardir01-dir JobId 2736: Start Backup JobId 2736, Job=XXXXXdbscluster01-mysql-job.2017-07-22_22.20.00_44
22-Jul 22:29 XXXXXtestbardir01-dir JobId 2736: There are no more Jobs associated with Volume “XXXXX-mysql-inc-0238”. Marking it purged.
22-Jul 22:29 XXXXXtestbardir01-dir JobId 2736: All records pruned from Volume “XXXXX-mysql-inc-0238”; marking it “Purged”
22-Jul 22:29 XXXXXtestbardir01-dir JobId 2736: Recycled volume “XXXXX-mysql-inc-0238”
22-Jul 22:29 XXXXXtestbardir01-dir JobId 2736: Using Device “XXXXXtestDrive01” to write.
22-Jul 22:29 XXXXXdbs06 JobId 2736: python-fd: Got to_lsn 3805643369005 from restore object of job 2734
22-Jul 22:29 XXXXXtestbarsd01-sd JobId 2736: Recycled volume “XXXXX-mysql-inc-0238” on device “XXXXXtestDrive01” (/backup/file), all previous data lost.
22-Jul 22:29 XXXXXtestbardir01-dir JobId 2736: Max Volume jobs=1 exceeded. Marking Volume “XXXXX-mysql-inc-0238” as Used.
22-Jul 22:29 XXXXXdbs06 JobId 2736: python-fd: Starting backup of /_percona/xbstream.0000002736
22-Jul 22:44 XXXXXdbs06 JobId 2736: python-fd: Starting backup of /_percona/xtrabackup_checkpoints
22-Jul 22:44 XXXXXtestbarsd01-sd JobId 2736: Elapsed time=00:14:37, Transfer rate=15.50 K Bytes/second
22-Jul 22:44 XXXXXtestbardir01-dir JobId 2736: Bareos XXXXXtestbardir01-dir 16.2.5 (03Mar17):
Build OS: x86_64-pc-linux-gnu ubuntu Ubuntu 14.04.5 LTS
JobId: 2736
Job: XXXXXdbscluster01-mysql-job.2017-07-22_22.20.00_44
Backup Level: Incremental, since=2017-07-22 21:20:03
Client: “XXXXXdbscluster01” 16.2.4 (01Jul16) x86_64-pc-linux-gnu,ubuntu,Ubuntu 12.04 LTS,xUbuntu_12.04,x86_64
FileSet: “XXXXX-mysql-fileset” 2017-05-15 22:05:00
Pool: “XXXXX-mysql-inc-pool” (From Job IncPool override)
Catalog: “XXXXXtestCatalog” (From Client resource)
Storage: “XXXXXtestbarsd01-sd” (From Job resource)
Scheduled time: 22-Jul-2017 22:20:00
Start time: 22-Jul-2017 22:29:43
End time: 22-Jul-2017 22:44:20
Elapsed time: 14 mins 37 secs
Priority: 10
FD Files Written: 2
SD Files Written: 2
FD Bytes Written: 13,599,028 (13.59 MB)
SD Bytes Written: 13,599,590 (13.59 MB)
Rate: 15.5 KB/s
Software Compression: 87.7 % (gzip)
VSS: no
Encryption: no
Accurate: no
Volume name(s): XXXXX-mysql-inc-0238
Volume Session Id: 1008
Volume Session Time: 1498057792
Last Volume Bytes: 13,628,227 (13.62 MB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK