Bacula-users

Re: [Bacula-users] backup upgraded to FULL for no apparent reason

2010-09-16 08:46:59
Subject: Re: [Bacula-users] backup upgraded to FULL for no apparent reason
From: Silver Salonen <silver AT ultrasoft DOT ee>
To: bacula-users AT lists.sourceforge DOT net
Date: Thu, 16 Sep 2010 15:44:25 +0300
On Thursday 16 September 2010 15:25:07 Martin Simmons wrote:
> >>>>> On Wed, 15 Sep 2010 17:08:33 +0300, Silver Salonen said:
> > 
> > On Wednesday 15 September 2010 16:49:18 Martin Simmons wrote:
> > > >>>>> On Wed, 15 Sep 2010 08:53:07 +0300, Silver Salonen said:
> > > > 
> > > > On Tuesday 14 September 2010 21:54:21 Silver Salonen wrote:
> > > > > On 14.09.2010 18:48, Martin Simmons wrote:
> > > > > >>>>>> On Tue, 14 Sep 2010 15:54:11 +0300, Silver Salonen said:
> > > > > >>
> > > > > >> On Tuesday 14 September 2010 15:16:47 Martin Simmons wrote:
> > > > > >>>>>>>> On Tue, 14 Sep 2010 13:49:59 +0300, Silver Salonen said:
> > > > > >>>>
> > > > > >>>> On Tuesday 14 September 2010 10:59:09 Christian Manal wrote:
> > > > > >>>>> Am 14.09.2010 09:53, schrieb Silver Salonen:
> > > > > >>>>>> On Tuesday 14 September 2010 10:41:38 Christian Manal wrote:
> > > > > >>>>>>> Am 14.09.2010 09:30, schrieb Silver Salonen:
> > > > > >>>>>>>> On Tuesday 14 September 2010 10:13:49 Christian Manal wrote:
> > > > > >>>>>>>>> Am 14.09.2010 08:36, schrieb Silver Salonen:
> > > > > >>>>>>>>>> Hello.
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>> I use Bacula 5.0.2 on FreeBSD 8.0. I have a huge 
> > > > > >>>>>>>>>> archive-type backup that has no full backup in its 
> > > > > >>>>>>>>>> schedule:
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>> Schedule {
> > > > > >>>>>>>>>>          Name = Archive
> > > > > >>>>>>>>>>          Run = Level=Differential 1st fri at 23:05
> > > > > >>>>>>>>>>          Run = Level=Incremental 2nd-5th fri at 23:05
> > > > > >>>>>>>>>>          Run = Level=Incremental sat-thu at 23:05
> > > > > >>>>>>>>>> }
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>> The job builds its fileset dynamically with "/usr/bin/find 
> > > > > >>>>>>>>>> /path/to/backup -type f -mtime +90d -print" - it takes a 
> > > > > >>>>>>>>>> while, but does its job. From time-to-time the job just 
> > > > > >>>>>>>>>> gets upgraded to full.. like today:
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>> 13-Sep 23:05 velvet-dir JobId 9135: 13-Sep 23:05 
> > > > > >>>>>>>>>> velvet-dir JobId 9135: No prior or suitable Full backup 
> > > > > >>>>>>>>>> found in catalog. Doing FULL backup.
> > > > > >>>>>>>>>> 13-Sep 23:05 velvet-dir JobId 9135: Start Backup JobId 
> > > > > >>>>>>>>>> 9135, Job=userdata-archive.2010-09-13_23.05.01_05
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>> Any ideas why this happens?
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>> Is there a way to continue with incremental backups once 
> > > > > >>>>>>>>>> such a full backup has been cancelled (eg. modifying 
> > > > > >>>>>>>>>> Bacula DB manually)? It would really hurt to start from 
> > > > > >>>>>>>>>> scratch with this archive.
> > > > > >>>>>>>>>>
> > > > > >>>>>>>>>
> > > > > >>>>>>>>>
> > > > > >>>>>>>>> Hi,
> > > > > >>>>>>>>>
> > > > > >>>>>>>>> did you set "Ignore FileSet Changes = yes" in your FileSet's
> > > > > >>>>>>>>> "Options"-Section? If not, the job level will be elevated 
> > > > > >>>>>>>>> to full, if
> > > > > >>>>>>>>> the FileSet changes.
> > > > > >>>>>>>>>
> > > > > >>>>>>>>>
> > > > > >>>>>>>>> Regards,
> > > > > >>>>>>>>> Christian Manal
> > > > > >>>>>>>>
> > > > > >>>>>>>> Yes I did. Otherwise the job would be upgraded to full every 
> > > > > >>>>>>>> time :)
> > > > > >>>>>>>>
> > > > > >>>>>>>
> > > > > >>>>>>> Well, it could have been, that the dynamically generated 
> > > > > >>>>>>> FileSet only
> > > > > >>>>>>> changes now and then.
> > > > > >>>>>>
> > > > > >>>>>> The dataset is big enough to contain at least a modified file 
> > > > > >>>>>> for every day :)
> > > > > >>>>>>
> > > > > >>>>>>>> This upgrade happened now after 35 days, ie the full backup 
> > > > > >>>>>>>> was done 35 days ago, on 10th of August. Meanwhile only 
> > > > > >>>>>>>> incrementals/differentials were done.
> > > > > >>>>>>>>
> > > > > >>>>>>>
> > > > > >>>>>>> What about your retention periods? Maybe the job or volume of 
> > > > > >>>>>>> the last
> > > > > >>>>>>> full backup got pruned.
> > > > > >>>>>>
> > > > > >>>>>> Retention period of the full volume is 10 years. The client's 
> > > > > >>>>>> file and job retention periods are 6 months. So I don't think 
> > > > > >>>>>> configuration of any of these parameters' could have caused 
> > > > > >>>>>> that.
> > > > > >>>>>>
> > > > > >>>>>> --
> > > > > >>>>>> Silver
> > > > > >>>>>>
> > > > > >>>>>
> > > > > >>>>>
> > > > > >>>>> Then I'm out of ideas. Sorry.
> > > > > >>>>>
> > > > > >>>>> Regards,
> > > > > >>>>> Christian Manal
> > > > > >>>>
> > > > > >>>> Thanks anyway. Any other ideas anyone?
> > > > > >>>
> > > > > >>> Is the Full job still shown by the list jobs command (i.e. is it 
> > > > > >>> still in the
> > > > > >>> catalog at all)?
> > > > > >>
> > > > > >> Yes, with job status "A".
> > > > > >
> > > > > > Status "A" is a failure code for "Cancelled".  Is that what you 
> > > > > > expected?
> > > > > > Bacula will ignore that job when looking for the prior Full backup, 
> > > > > > but you
> > > > > > can use delete jobid=... to delete it from the catalog.
> > > > > >
> > > > > > Is there an older one still in the list as well?
> > > > > 
> > > > > Yes, the list has all the jobs since beginning of times, including 
> > > > > the 
> > > > > successful FULL one :)
> > > > > 
> > > > > I now deleted the cancelled job from the list - let's see what 
> > > > > happens 
> > > > > today evening.
> > > > > 
> > > > > >>> What did the last successful incremental print for the "Backup 
> > > > > >>> Level" in the
> > > > > >>> log.  It should give a date.
> > > > > >>
> > > > > >> The last incremental backup was not different from other 
> > > > > >> incrementals.
> > > > > >>
> > > > > >> 12-Sep 23:05 velvet-dir JobId 9130: Start Backup JobId 9130, 
> > > > > >> Job=userdata-archive.2010-09-12_23.05.04_00
> > > > > >> 12-Sep 23:05 velvet-dir JobId 9130: There are no more Jobs 
> > > > > >> associated with Volume "userdata-archive-incr-0315". Marking it 
> > > > > >> purged.
> > > > > >> 12-Sep 23:05 velvet-dir JobId 9130: All records pruned from Volume 
> > > > > >> "userdata-archive-incr-0315"; marking it "Purged"
> > > > > >> 12-Sep 23:05 velvet-dir JobId 9130: Recycled volume 
> > > > > >> "userdata-archive-incr-0315"
> > > > > >> 12-Sep 23:05 velvet-dir JobId 9130: Using Device "device-archive"
> > > > > >> 12-Sep 23:19 velvet-dir JobId 9130: Sending Accurate information.
> > > > > >> 12-Sep 23:21 velvet-sd JobId 9130: Recycled volume 
> > > > > >> "userdata-archive-incr-0315" on device "device-archive" 
> > > > > >> (/mnt/backup/bacula/), all previous data lost.
> > > > > >> 12-Sep 23:21 velvet-dir JobId 9130: Max Volume jobs exceeded. 
> > > > > >> Marking Volume "userdata-archive-incr-0315" as Used.
> > > > > >> 12-Sep 23:59 velvet-sd JobId 9130: Job write elapsed time = 
> > > > > >> 00:37:46, Transfer rate = 19  Bytes/second
> > > > > >
> > > > > > You chopped the part I wanted to see.  Please post the whole job 
> > > > > > log, down to
> > > > > > the start of the next job.
> > > > > 
> > > > > This is from the e-mail Bacula server sent:
> > > > > 
> > > > > 12-Sep 23:05 velvet-dir JobId 9130: Start Backup JobId 9130, 
> > > > > Job=userdata-archive.2010-09-12_23.05.04_00
> > > > > 12-Sep 23:05 velvet-dir JobId 9130: There are no more Jobs associated 
> > > > > with Volume "userdata-archive-incr-0315". Marking it purged.
> > > > > 12-Sep 23:05 velvet-dir JobId 9130: All records pruned from Volume 
> > > > > "userdata-archive-incr-0315"; marking it "Purged"
> > > > > 12-Sep 23:05 velvet-dir JobId 9130: Recycled volume 
> > > > > "userdata-archive-incr-0315"
> > > > > 12-Sep 23:05 velvet-dir JobId 9130: Using Device "device-archive"
> > > > > 12-Sep 23:19 velvet-dir JobId 9130: Sending Accurate information.
> > > > > 12-Sep 23:21 velvet-sd JobId 9130: Recycled volume 
> > > > > "userdata-archive-incr-0315" on device "device-archive" 
> > > > > (/mnt/backup/bacula/), all previous data lost.
> > > > > 12-Sep 23:21 velvet-dir JobId 9130: Max Volume jobs exceeded. Marking 
> > > > > Volume "userdata-archive-incr-0315" as Used.
> > > > > 12-Sep 23:59 velvet-fd JobId 9130:      Could not stat 
> > > > > "/usr/local/repositories": ERR=No such file or directory
> > > > > 12-Sep 23:59 velvet-sd JobId 9130: Job write elapsed time = 00:37:46, 
> > > > > Transfer rate = 19  Bytes/second
> > > > > 12-Sep 23:59 velvet-dir JobId 9130: Bacula velvet-dir 5.0.2 
> > > > > (28Apr10): 
> > > > > 12-Sep-2010 23:59:46
> > > > >    Build OS:               amd64-portbld-freebsd8.0 freebsd 
> > > > > 8.0-RELEASE-p2
> > > > >    JobId:                  9130
> > > > >    Job:                    userdata-archive.2010-09-12_23.05.04_00
> > > > >    Backup Level:           Incremental, since=2010-09-11 23:23:00
> > > > >    Client:                 "velvet-fd" 5.0.2 (28Apr10) 
> > > > > amd64-portbld-freebsd8.0,freebsd,8.0-RELEASE-p2
> > > > >    FileSet:                "userdata-archive" 2009-05-01 23:05:00
> > > > >    Pool:                   "pool-userdata-archive-incr" (From Job 
> > > > > IncPool override)
> > > > >    Catalog:                "MySQL" (From Client resource)
> > > > >    Storage:                "storage-archive" (From Job resource)
> > > > >    Scheduled time:         12-Sep-2010 23:05:03
> > > > >    Start time:             12-Sep-2010 23:19:20
> > > > >    End time:               12-Sep-2010 23:59:46
> > > > >    Elapsed time:           40 mins 26 secs
> > > > >    Priority:               10
> > > > >    FD Files Written:       193
> > > > >    SD Files Written:       193
> > > > >    FD Bytes Written:       17,283 (17.28 KB)
> > > > >    SD Bytes Written:       44,068 (44.06 KB)
> > > > >    Rate:                   0.0 KB/s
> > > > >    Software Compression:   None
> > > > >    VSS:                    no
> > > > >    Encryption:             no
> > > > >    Accurate:               yes
> > > > >    Volume name(s):         userdata-archive-incr-0315
> > > > >    Volume Session Id:      174
> > > > >    Volume Session Time:    1279692875
> > > > >    Last Volume Bytes:      47,615 (47.61 KB)
> > > > >    Non-fatal FD errors:    1
> > > > >    SD Errors:              0
> > > > >    FD termination status:  OK
> > > > >    SD termination status:  OK
> > > > >    Termination:            Backup OK -- with warnings
> > > > 
> > > > After deleting the cancelled full job, the next incremental job was 
> > > > still upgraded to full. I then deleted the last successful incremental 
> > > > job record from database too, but the job is still upgraded to full.
> > > > 
> > > > Anything else to try?
> > > 
> > > We need to find out why Bacula is rejecting the full backup.
> > > 
> > > Please post the complete output from the incorrectly upgraded job as well.
> > > 
> > > It would also be useful to see the output of
> > > 
> > > llist jobid=aaa
> > > llist jobid=bbb
> > > llist jobid=ccc
> > > 
> > > where:
> > > 
> > > aaa is the jobid of the last good full backup.
> > > bbb is the jobid of the last good incremental backup still in the catalog
> > > ccc is the jobid of the incorrectly upgraded job.
> > 
> > Here they come :)
> > 
> > BTW, thanks for looking into it.
> > 
> > A)
> > 
> > 1000 OK: velvet-dir Version: 5.0.3 (04 August 2010)
> > Enter a period to cancel a command.
> > llist jobid=8960
> > Automatically selected Catalog: MySQL
> > Using Catalog "MySQL"
> >            JobId: 8,960
> >              Job: userdata-archive.2010-08-09_23.05.00_06
> >             Name: userdata-archive
> >      PurgedFiles: 0
> >             Type: B
> >            Level: F
> >         ClientId: 1
> >             Name: fd
> >        JobStatus: T
> >        SchedTime: 2010-08-09 23:05:00
> >        StartTime: 2010-08-09 23:19:25
> >          EndTime: 2010-08-10 22:13:35
> >      RealEndTime: 2010-08-10 22:13:35
> >         JobTDate: 1,281,467,615
> >     VolSessionId: 4
> >   VolSessionTime: 1,279,692,875
> >         JobFiles: 1,086,225
> >        JobErrors: 1
> >  JobMissingFiles: 0
> >           PoolId: 24
> >         PooLname: pool-userdata-archive-full
> >       PriorJobId: 0
> >        FileSetId: 10
> >          FileSet: userdata-archive
> > 
> > B)
> > 
> > 1000 OK: velvet-dir Version: 5.0.3 (04 August 2010)
> > Enter a period to cancel a command.
> > llist jobid=9110
> > Automatically selected Catalog: MySQL
> > Using Catalog "MySQL"
> >            JobId: 9,110
> >              Job: userdata-archive.2010-09-08_23.05.02_40
> >             Name: userdata-archive
> >      PurgedFiles: 0
> >             Type: B
> >            Level: I
> >         ClientId: 1
> >             Name: fd
> >        JobStatus: T
> >        SchedTime: 2010-09-08 23:05:02
> >        StartTime: 2010-09-08 23:23:01
> >          EndTime: 2010-09-09 00:12:52
> >      RealEndTime: 2010-09-09 00:12:52
> >         JobTDate: 1,283,980,372
> >     VolSessionId: 154
> >   VolSessionTime: 1,279,692,875
> >         JobFiles: 4,365
> >        JobErrors: 1
> >  JobMissingFiles: 0
> >           PoolId: 25
> >         PooLname: pool-userdata-archive-incr
> >       PriorJobId: 0
> >        FileSetId: 10
> >          FileSet: userdata-archive
> > 
> > C)
> > 
> > 1000 OK: velvet-dir Version: 5.0.3 (04 August 2010)
> > Enter a period to cancel a command.
> > llist jobid=9142
> > Automatically selected Catalog: MySQL
> > Using Catalog "MySQL"
> >            JobId: 9,142
> >              Job: userdata-archive.2010-09-15_08.50.38_19
> >             Name: userdata-archive
> >      PurgedFiles: 0
> >             Type: B
> >            Level: F
> >         ClientId: 1
> >             Name: fd
> >        JobStatus: A
> >        SchedTime: 2010-09-15 08:50:26
> >        StartTime: 2010-09-15 08:50:40
> >          EndTime: 2010-09-15 09:05:07
> >      RealEndTime: 2010-09-15 09:05:07
> >         JobTDate: 1,284,530,707
> >     VolSessionId: 6
> >   VolSessionTime: 1,284,447,278
> >         JobFiles: 0
> >        JobErrors: 1
> >  JobMissingFiles: 0
> >           PoolId: 24
> >         PooLname: pool-userdata-archive-full
> >       PriorJobId: 0
> >        FileSetId: 10
> >          FileSet: userdata-archive
> 
> Those look normal to me, so they don't explain why job 9142 was upgraded.
> 
> Does the job resource specify Max Full Interval?  Bacula seems to be ignoring
> Full jobs older than 30 days / 1 month.
> 
> If not, then try running with
> 
> setdebug director level=100 trace=1
> 
> The 50 lines in the trace file around the one that looks like
> 
> have_full=... do_full=... now=... full_time=...
> 
> would be useful to see.

Oh, that's just embarrasing - the job really had "Max Full Interval = 34d" 
specified through JobDefs.. I set it to 0 now and the incremental job ran OK.

Sorry for such a silly mistake and thank you very much for the support, Martin.

PS. The "error" message could be a bit cleaner though - not that FULL was not 
found, but rather than the FULL was not found within the specified interval or 
smth. 

-- 
Silver

------------------------------------------------------------------------------
Start uncovering the many advantages of virtual appliances
and start using them to simplify application deployment and
accelerate your shift to cloud computing.
http://p.sf.net/sfu/novell-sfdev2dev
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users

<Prev in Thread] Current Thread [Next in Thread>