# unable to restore due to wrong from\_lsn referential

**URL:** <https://forums.percona.com/t/unable-to-restore-due-to-wrong-from-lsn-referential/5760>\
**Category:** Percona XtraBackup\
**Created:** [July 23, 2017, 2:07pm UTC](https://forums.percona.com/t/unable-to-restore-due-to-wrong-from-lsn-referential/5760 "2017-07-23T14:07:47Z")\
**Posts on this page:** 2\
**Page:** 1

<div class="post-metadata">

**Author:** ![PeterC](https://avatars.discourse-cdn.com/v4/letter/p/f9ae1b/32.png) [@PeterC](https://forums.percona.com/u/PeterC)\
**Post date:** [July 23, 2017, 2:07pm UTC](https://forums.percona.com/t/unable-to-restore-due-to-wrong-from-lsn-referential/5760/1 "2017-07-23T14:07:47Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![PeterC](https://avatars.discourse-cdn.com/v4/letter/p/f9ae1b/32.png) [@PeterC](https://forums.percona.com/u/PeterC)\
**Post date:** [July 24, 2017, 1:52pm UTC](https://forums.percona.com/t/unable-to-restore-due-to-wrong-from-lsn-referential/5760/2 "2017-07-24T13:52:36Z")

</div>

## 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