Bacula-users

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

2010-09-16 08:28:03
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 13:25:07 +0100
>>>>> 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.

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