Bacula-users

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

2010-09-16 09:50:09
Subject: Re: [Bacula-users] backup upgraded to FULL for no apparent reason
From: Martin Simmons <martin AT lispworks DOT com>
To: bacula-users AT lists.sourceforge DOT net
Date: Thu, 16 Sep 2010 14:47:05 +0100
>>>>> On Thu, 16 Sep 2010 15:44:25 +0300, Silver Salonen said:
> 
> 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.

I'm glad it was resolved finally!


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

Yes, that would be an improvement.

__Martin

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