[ERROR] : [ backupSnapshot->getLsn: Error: Could not find file /backup/tds/xbm/blr-cos-mtarc.digi.com/271/xtrabackup_checkpoints for log sequence information. ]
Prashant
I accidentally deleted the contents of backup folder, as I was running
out of storage space. When I run the backup command for my host once
again as:
./xbm backup run "mybackuphost.mydomain.com" "NightlyBackup"
I get the following output on the screen:
================================================
XtraBackup Manager v0.7 - Copyright 2011 Marin Software
2012-01-05 12:32:01 [INFO] : [ Initializing Scheduled Backup
"NightlyBackup" (ID #21) for host: mybackuphost.mydomain.com ... ]
2012-01-05 12:32:01 [INFO] : [ Using Backup Strategy: Rotating sets of
Incremental Backups ]
2012-01-05 12:32:01 [INFO] : [ Using DAY_OF_WEEK as the rotation
method... ]
2012-01-05 12:32:01 [INFO] : [ Set to rotate on: Sunday ]
2012-01-05 12:32:01 [INFO] : [ This backup was launched on a
Thursday ]
2012-01-05 12:32:01 [INFO] : [ Based on the launch time of this
backup, no rotation should occur today - proceeding to take an
incremental. ]
2012-01-05 12:32:01 [INFO] : [ Attempting to find available ports for
use... ]
2012-01-05 12:32:01 [INFO] : [ Got lock on port 10000. ]
2012-01-05 12:32:01 [ERROR] : [ backupSnapshot->getLsn: Error: Could
not find file /backup/tds/xbm/mybackuphost.mydomain.com/271/
xtrabackup_checkpoints for log sequence information. ]
2012-01-05 12:32:01 [INFO] : [ Released lock on port 10000. ]
cliHandler.class.php: backupSnapshot->getLsn: Error: Could not find
file /backup/tds/xbm/mybackuphost.mydomain.com/271/
xtrabackup_checkpoints for log sequence information.
Trace:
#0 /home/xbm/xtrabackup-manager/includes/
rotatingBackupTaker.class.php(279): genericBackupTaker-
>takeIncrementalBackupSnapshot(Object(scheduledBackup),
Object(backupSnapshotGroup), Object(backupSnapshot))
#1 /home/xbm/xtrabackup-manager/includes/
backupSnapshotTaker.class.php(182): rotatingBackupTaker-
>takeScheduledBackupSnapshot(Object(scheduledBackup))
#2 /home/xbm/xtrabackup-manager/includes/cliHandler.class.php(875):
backupSnapshotTaker-
>takeScheduledBackupSnapshot(Object(scheduledBackup))
#3 /home/xbm/xtrabackup-manager/includes/cliHandler.class.php(97):
cliHandler->handleBackupActions(Array)
#4 /home/xbm/xtrabackup-manager/xbm(36): cliHandler-
>handleArguments(Array)
================================================
The xbm.log is
===================================================
2012-01-05 12:52:44 [DEBUG] : [ hostGetter->getByName: Sending SQL:
SELECT host_id FROM hosts WHERE hostname='mybackuphost.mydomain.com' ]
2012-01-05 12:52:44 [DEBUG] : [ hostGetter->getByName: Query took
0.0001068115234375 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackupGetter-
>getByHostnameAndName: Sending SQL: SELECT scheduled_backup_id FROM
scheduled_backups
WHERE host_id=21 AND name='NightlyBackup' ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackupGetter-
>getByHostnameAndName: Query took 3.9815902709961E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.0067901611328E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.3869018554688E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
5.1021575927734E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.6968460083008E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
3.9815902709961E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
SELECT queue_ticket_id, pid FROM queue_tickets WHERE
queue_name='scheduledBackup:21' ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
0.00023293495178223 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
DELETE FROM queue_tickets WHERE queue_ticket_id=1191 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
0.002129077911377 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->getTicketNumber: Sending
SQL: INSERT INTO queue_tickets (queue_ticket_id, queue_name,
entry_time, pid) VALUES (NULL, 'scheduledBackup:21', NOW(), 4998) ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->getTicketNumber: Query
took 0.0014798641204834 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
SELECT queue_ticket_id, pid FROM queue_tickets WHERE
queue_name='hostBackup:21' ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
0.00010108947753906 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->getTicketNumber: Sending
SQL: INSERT INTO queue_tickets (queue_ticket_id, queue_name,
entry_time, pid) VALUES (NULL, 'hostBackup:21', NOW(), 4998) ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->getTicketNumber: Query
took 0.0015220642089844 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
SELECT queue_ticket_id, pid FROM queue_tickets WHERE
queue_name='scheduledBackup:21' ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
0.00010514259338379 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue:
Sending SQL: SELECT queue_ticket_id FROM queue_tickets WHERE
queue_name='scheduledBackup:21' AND queue_ticket_id=1271 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue: Query
took 0.00011515617370605 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue:
Sending SQL: SELECT queue_ticket_id FROM queue_tickets WHERE
queue_name='scheduledBackup:21' ORDER BY entry_time ASC LIMIT 1 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue: Query
took 0.00012493133544922 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
SELECT queue_ticket_id, pid FROM queue_tickets WHERE
queue_name='hostBackup:21' ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
9.918212890625E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue:
Sending SQL: SELECT queue_ticket_id FROM queue_tickets WHERE
queue_name='hostBackup:21' AND queue_ticket_id=1281 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue: Query
took 0.00010395050048828 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue:
Sending SQL: SELECT queue_ticket_id FROM queue_tickets WHERE
queue_name='hostBackup:21' ORDER BY entry_time ASC LIMIT 1 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue: Query
took 0.0001060962677002 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
SELECT queue_ticket_id, pid FROM queue_tickets WHERE
queue_name='scheduledBackup:GLOBAL' ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
0.00010395050048828 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->getTicketNumber: Sending
SQL: INSERT INTO queue_tickets (queue_ticket_id, queue_name,
entry_time, pid) VALUES (NULL, 'scheduledBackup:GLOBAL', NOW(),
4998) ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->getTicketNumber: Query
took 0.0026860237121582 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Sending SQL:
SELECT queue_ticket_id, pid FROM queue_tickets WHERE
queue_name='scheduledBackup:GLOBAL' ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->cleanQueue: Query took
0.0001068115234375 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue:
Sending SQL: SELECT queue_ticket_id FROM queue_tickets WHERE
queue_name='scheduledBackup:GLOBAL' AND queue_ticket_id=1291 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue: Query
took 9.9897384643555E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue:
Sending SQL: SELECT queue_ticket_id FROM queue_tickets WHERE
queue_name='scheduledBackup:GLOBAL' ORDER BY entry_time ASC LIMIT 1 ]
2012-01-05 12:52:44 [DEBUG] : [ queueManager->checkFrontOfQueue: Query
took 0.00016307830810547 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.2915344238281E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.6014785766602E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getParameters:
Sending SQL: SELECT bsp.param_name, sbp.param_value FROM
scheduled_backups sb JOIN backup_strategy_params bsp
ON sb.backup_strategy_id = bsp.backup_strategy_id
JOIN scheduled_backup_params sbp
ON sbp.scheduled_backup_id = sb.scheduled_backup_id AND
bsp.backup_strategy_param_id = sbp.backup_strategy_param_id
WHERE
sb.scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getParameters: Query
took 4.1007995605469E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup-
>getSnapshotGroupsNewestToOldest: Sending SQL: SELECT DISTINCT
snapshot_group_num FROM backup_snapshots WHERE scheduled_backup_id=21
AND status='COMPLETED' ORDER BY snapshot_group_num DESC ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup-
>getSnapshotGroupsNewestToOldest: Query took 0.00022006034851074 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.6968460083008E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.6014785766602E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.5061111450195E-05 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Sending SQL:
SELECT sb.*, bs.strategy_code, bs.strategy_name FROM scheduled_backups
sb JOIN backup_strategies bs ON
sb.backup_strategy_id=bs.backup_strategy_id WHERE
scheduled_backup_id=21 ]
2012-01-05 12:52:44 [DEBUG] : [ scheduledBackup->getInfo: Query took
4.1961669921875E-05 ]
===================================================
How do we resolve this and handle this when someone accidentally
deletes the previously backed up contents?
BTW, one workaround for this is
1. to delete the backup job in the database by:
delete from scheduled_backups where host_id=xy;
where xy=host_id obtained by running the query:
select host_id from hosts where hostname='mybackuphost.mydomain.com';
2.add the backup job once again as:
./xbm backup add "mybackuphost.mydomain.com" "NightlyBackup" ROTATING
"xx ab * * *" "Backup" /var/lib/mysql/data myuser "secure-pw"
3. then run the backup job as ./xbm backup run
"mybackuphost.mydomain.com" "NightlyBackup"
Thanks & Regards
Prashant
Lachlan Mulcahy
On 04/01/2012, at 11:32 PM, Prashant wrote:
> Hi ALL,
>
> I accidentally deleted the contents of backup folder, as I was running
> out of storage space. When I run the backup command for my host once
> again as:
>
> ./xbm backup run "mybackuphost.mydomain.com" "NightlyBackup"
>
> I get the following output on the screen:
> ================================================
<snip>
> 2012-01-05 12:32:01 [ERROR] : [ backupSnapshot->getLsn: Error: Could
> not find file /backup/tds/xbm/mybackuphost.mydomain.com/271/
> xtrabackup_checkpoints for log sequence information. ]
<snip>
> How do we resolve this and handle this when someone accidentally
> deletes the previously backed up contents?
First a little background on the error which might add some context...
This error comes about when the next backup starts running and it goes looking for metadata on the most recently taken backup. This metadata is stored in a file that is created by XtraBackup itself called xtrabackup_checkpoints.
The most important piece of information that it needs is the log sequence number (LSN) which is sort of like a global version number for the whole of your InnoDB data. As pages are changed in the database the log sequence number is incremented and each page is marked with the log sequence number at the time it is updated.
XtraBackup uses this log sequence information when doing incremental backups.
When XtraBackup Manager starts the next incremental backup it tells XtraBackup the log sequence number of the last backup (pulled from the xtrabackup_checkpoints file), then XtraBackup scans all the pages of your database and looks for the ones with a higher log sequence number and this is how it creates the incremental backup (just the set of changes since the last backup).
Without this information, we can't proceed with the next backup, so this is why we get that fatal error.
As for how to fix it - You would need to delete the Scheduled Backup Task and recreate it.
Normally you would use the command syntax: xbm backup delete <hostname> <backup name>
This should delete the backup task and allow you to recreate it.
I did a quick test in my environment and it seemed to work OK.
> BTW, one workaround for this is
> 1. to delete the backup job in the database by:
> delete from scheduled_backups where host_id=xy;
> where xy=host_id obtained by running the query:
> select host_id from hosts where hostname='mybackuphost.mydomain.com';
>
> 2.add the backup job once again as:
> ./xbm backup add "mybackuphost.mydomain.com" "NightlyBackup" ROTATING
> "xx ab * * *" "Backup" /var/lib/mysql/data myuser "secure-pw"
>
> 3. then run the backup job as ./xbm backup run
> "mybackuphost.mydomain.com" "NightlyBackup"
These steps will work, but will leave some "orphaned" rows in other tables in the database. They should not really hurt anything of course, but it is nice to keep things clean and tidy :)
If you encounter the issue again, please try using "xbm backup delete" to delete the backup task and recreate it. Obviously I'd aim for people to be able to clean up accidents like this without having to hack around in the DB themselves :)
Thanks again for trying it out and I'm glad to be getting your feedback!
Best Regards,
Lachlan
Prashant N
I tried to delete the scheduled backup set by:
./xbm backup delete "myhost" "NightlyBackup"
This results in:
=================================
The Scheduled Backup Task for host: myhost with name: NightlyBackup
has 2 backup snapshots associated with it.
If you delete this Scheduled Backup Task, all associated backup
snapshots will be removed -- this cannot be undone.
PHP Fatal error: Call to undefined function readline() in
/home/xbm/xtrabackup-manager/includes/cliHandler.class.php on line 808
=================================
Thats why I went to db way.
BTW, if we can delete snapshots by anyway like
./xbm snapshot delete myhostname (list and then proceed to delete
snapshots based on ID's)
--
Thanks & Regards
Prashant N
Lachlan Mulcahy
On 05/01/2012, at 10:11 PM, Prashant N wrote:
> I tried to delete the scheduled backup set by:
>
> ./xbm backup delete "myhost" "NightlyBackup"
>
> This results in:
> =================================
> The Scheduled Backup Task for host: myhost with name: NightlyBackup
> has 2 backup snapshots associated with it.
>
> If you delete this Scheduled Backup Task, all associated backup
> snapshots will be removed -- this cannot be undone.
>
> PHP Fatal error: Call to undefined function readline() in
> /home/xbm/xtrabackup-manager/includes/cliHandler.class.php on line 808
> =================================
I made a Google Code Issues entry here:
http://code.google.com/p/xtrabackup-manager/issues/detail?id=43
It looks like some PHP packages do not include readline functions as they do on my test platform. I have adjusted the code to use it's own implementation of readline functionality, so you should no longer see this error on the latest version of the code.
> Thats why I went to db way.
>
> BTW, if we can delete snapshots by anyway like
>
> ./xbm snapshot delete myhostname (list and then proceed to delete
> snapshots based on ID's)
The reason we do not allow deletion of single snapshots is that it can make most other backup snapshots in the chain useless / broken.
If you have the full backup F and then 3 incrementals each day called I1, I2 and I3 they exist as a sort of chain like this:
F -> I1 -> I2 -> I3
If you wanted to recover to I3, you would start with F and then apply each I1,I2..etc. necessary from left to right to reach the desired restore point.
So if we allowed to delete I1, it would make I2 and I3 no longer useable.
For this reason, we keep things simplified and allow to only delete the entire backup task and all associated backups. It is possible more functionality may be added in the future, but the aim is to get to a stable 1.0 release with all of the basics needed.
I hope this explains a bit why that functionality is not there.
Thanks,
Lachlan
Lachlan Mulcahy
There was a delay in getting my fix pushed for this readline issue, but it is committed now as rev 207.
Please update to that revision and see if you still get any issues when running the delete.
Thanks,
Lachlan
On 05/01/2012, at 10:11 PM, Prashant N wrote:
Lachlan Mulcahy
On 05/01/2012, at 10:11 PM, Prashant N wrote:
Prashant N
schedule. works as expected.
Now trying with scheduled backup jobs