Bacula-users

[Bacula-users] File jobs purged when they should not

2012-11-20 11:27:43
Subject: [Bacula-users] File jobs purged when they should not
From: Felip Moll <lipixx AT gmail DOT com>
To: bacula-users AT lists.sourceforge DOT net
Date: Tue, 20 Nov 2012 17:23:21 +0100
Hi people,

Recently I found a problem when trying to recover my files from a Job. The Files of a Job are purged when they shouldn't be.

For example:


On 1st November a job of 1TB data run. All went well. The Job was an Incremental done every 6 months but it didn't find any previous Full backup, so it performed a full backup. The job take two tapes, the 11L and part of the 12L. The fact is that I tried to do a selective restore from this backup but the job is marked as "purged"!. Mi FileRetention is 6 months, my Job retention 12 months, and my Volume retention 12 months also.
What can be the problem?
All other jobs that run after this went well and I can navigate through their files.
I see that the job is marked as "purged" in the "status" field of the job in the bacula-gui console.

I use a Bacula version 5.0.3 (pretty old but I need to know if its a problem of my config or a bug of this version), in a production server.

I changed my configs, and I reset all the daemons.
I tried to make and restore backups from other pools, and after some days all of them gets purged. For example, another is an Incremental Backup made on 12-11-2012 that went into the 4 weeks Pool, and today at 20-Nov-2012 the list of Files got purged. All my volumes are updated and checked that are ok to have the correct retention policy.

Is it possible that if I have a pool of 7 days ret. period the purge done for the clients that use this pool affect also other pools? It shouldn't.

Below you can see the log for the first example job, my relevant configs and a try to restore this backup.

Thank you for your help!.


#######################
#######################   LOG for example of purged Files JOB
#######################
01-nov 22:00 gollum-dir JobId 7444: No prior Full backup Job record found.
01-nov 22:00 gollum-dir JobId 7444: No prior or suitable Full backup found in catalog. Doing FULL backup.
01-nov 22:00 gollum-dir JobId 7444: Start Backup JobId 7444, Job=Backup_Dades_:_Dominator_6m.2012-11-01_22.00.00_11
01-nov 22:00 gollum-sd JobId 7444: 3307 Issuing autochanger "unload slot 40, drive 0" command.
01-nov 22:02 gollum-dir JobId 7444: Using Device "Drive-1"
01-nov 22:02 gollum-sd JobId 7444: 3301 Issuing autochanger "loaded? drive 0" command.
01-nov 22:02 gollum-sd JobId 7444: 3302 Autochanger "loaded? drive 0", result: nothing loaded.
01-nov 22:02 gollum-sd JobId 7444: 3304 Issuing autochanger "load slot 30, drive 0" command.
01-nov 22:02 gollum-sd JobId 7444: 3305 Autochanger "load slot 30, drive 0", status is OK.
01-nov 22:02 gollum-sd JobId 7444: Volume "000011L4" previously written, moving to end of data.
01-nov 22:04 gollum-sd JobId 7444: Ready to append to end of Volume "000011L4" at file=1063.
01-nov 23:10 gollum-sd JobId 7444: End of Volume "000011L4" at 1160:4699 on device "Drive-1" (/dev/tape/by-id/scsi-35000e11135f4b001-nst). Write of 64512 bytes got -1.
01-nov 23:11 gollum-sd JobId 7444: Re-read of last block succeeded.
01-nov 23:11 gollum-sd JobId 7444: End of medium on Volume "000011L4" Bytes=1,157,417,210,880 Blocks=17,941,114 at 01-Nov-2012 23:11.
01-nov 23:11 gollum-sd JobId 7444: 3307 Issuing autochanger "unload slot 30, drive 0" command.
01-nov 23:11 gollum-dir JobId 7444: There are no more Jobs associated with Volume "000012L4". Marking it purged.
01-nov 23:11 gollum-dir JobId 7444: All records pruned from Volume "000012L4"; marking it "Purged"
01-nov 23:11 gollum-dir JobId 7444: Recycled volume "000012L4"
01-nov 23:11 gollum-sd JobId 7444: 3301 Issuing autochanger "loaded? drive 0" command.
01-nov 23:11 gollum-sd JobId 7444: 3302 Autochanger "loaded? drive 0", result: nothing loaded.
01-nov 23:11 gollum-sd JobId 7444: 3304 Issuing autochanger "load slot 11, drive 0" command.
01-nov 23:12 gollum-sd JobId 7444: 3305 Autochanger "load slot 11, drive 0", status is OK.
01-nov 23:12 gollum-sd JobId 7444: Recycled volume "000012L4" on device "Drive-1" (/dev/tape/by-id/scsi-35000e11135f4b001-nst), all previous data lost.
01-nov 23:12 gollum-sd JobId 7444: New volume "000012L4" mounted on device "Drive-1" (/dev/tape/by-id/scsi-35000e11135f4b001-nst) at 01-Nov-2012 23:12.
02-nov 06:54 gollum-sd JobId 7444: Job write elapsed time = 08:48:40, Transfer rate = 34.25 M Bytes/second
02-nov 06:55 gollum-dir JobId 7444: Bacula gollum-dir 5.0.3 (04Aug10): 02-nov-2012 06:55:58
Build OS: i686-pc-linux-gnu ubuntu 10.04
JobId: 7444
Job: Backup_Dades_:_Dominator_6m.2012-11-01_22.00.00_11
Backup Level: Full (upgraded from Incremental)
Client: "dominator-fd" 5.0.1 (24Feb10) x86_64-pc-linux-gnu,ubuntu,10.04
FileSet: "home" 2012-02-10 04:00:00
Pool: "Cintes-Data-6mesos" (From Job resource)
Catalog: "MyCatalog" (From Client resource)
Storage: "Autochanger" (From Job resource)
Scheduled time: 01-nov-2012 22:00:00
Start time: 01-nov-2012 22:02:20
End time: 02-nov-2012 06:55:58
Elapsed time: 8 hours 53 mins 38 secs
Priority: 10
FD Files Written: 934,016
SD Files Written: 934,016
FD Bytes Written: 1,086,481,969,095 (1.086 TB)
SD Bytes Written: 1,086,659,272,315 (1.086 TB)
Rate: 33933.5 KB/s
Software Compression: None
VSS: no
Encryption: no
Accurate: no
Volume name(s): 000011L4|000012L4
Volume Session Id: 711
Volume Session Time: 1345461527
Last Volume Bytes: 990,196,300,800 (990.1 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK

02-nov 06:55 gollum-dir JobId 7444: Begin pruning Jobs older than 6 months .
02-nov 06:55 gollum-dir JobId 7444: No Jobs found to prune.
02-nov 06:55 gollum-dir JobId 7444: Begin pruning Jobs.
02-nov 06:55 gollum-dir JobId 7444: No Files found to prune.
02-nov 06:55 gollum-dir JobId 7444: End auto prune.

#######################
#######################   RELEVANT CONFIGURATIONS
#######################

Job {
Name = "Backup Dades : Dominator 6m"
Client = dominator-fd
JobDefs = "JobTemplate"
Fileset = "home"
Schedule = "CicleMensual-6mesos-22h"
Storage = Autochanger
Pool = Cintes-Data-6mesos
}

Schedule {
Name = "CicleMensual-6mesos-22h"
Run = Full january 1 at 22:00
Run = Full july 1 at 22:00
Run = Incremental feb-jun 1 at 22:00
Run = Incremental aug-dec 1 at 22:00
}

Client {
Name = dominator-fd
Address = dominator.domain.com
FDPort = 9102
Catalog = MyCatalog
Password = "****" # password for FileDaemon
File Retention = 10 years # 10 years
Job Retention = 10 years # six months
AutoPrune = yes # Prune expired Jobs/Files
}



Pool {
Name = Cintes-Data-6mesos
Pool Type = Backup
Recycle = yes
AutoPrune = yes
File Retention = 1 month
Job Retention = 6 months
Volume Retention = 12 months
}

#######################
#######################
#######################

#######################
####################### What happens when I try to restore
#######################
Enter JobId(s), comma separated, to restore: 7444
You have selected the following JobId: 7444

Building directory tree for JobId(s) 7444 ...

For one or more of the JobIds selected, no files were found,
so file selection is not possible.
Most likely your retention policy pruned the files.

Do you want to restore all the files? (yes|no): no

Regexp matching files to restore? (empty to abort):
Restore not done.
*
#######################
#######################
#######################


------------------------------------------------------------------------------
Monitor your physical, virtual and cloud infrastructure from a single
web console. Get in-depth insight into apps, servers, databases, vmware,
SAP, cloud infrastructure, etc. Download 30-day Free Trial.
Pricing starts from $795 for 25 servers or applications!
http://p.sf.net/sfu/zoho_dev2dev_nov
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users