Bacula-users

Re: [Bacula-users] No log output from prune expired and truncate commands

2014-04-24 17:20:12
Subject: Re: [Bacula-users] No log output from prune expired and truncate commands
From: Kern Sibbald <kern AT sibbald DOT com>
To: "Brady, Mike" <mike.brady AT devnull.net DOT nz>, Bacula-users AT lists.sourceforge DOT net
Date: Thu, 24 Apr 2014 23:17:33 +0200
On 04/24/2014 10:37 PM, Brady, Mike wrote:
> On 2014-04-25 07:59, Brady, Mike wrote:
>> I am doing some testing with Bacula 7 and amongst other things am
>> looking at the prune expired and truncate console commands.
>>
>> I have added the following runscript to the BackupCatalog job
>>
>>    RunScript {
>>        RunsWhen=Before
>>        RunsOnClient=No
>>        Console = "prune expired volume yes"
>>        Console = "truncate allpools storage=FileStorage01"
>>    }
>>
>> This appears to be working in that the appropriate volumes are being
>> truncated when they should be, but all I see in the log is
>>
>> 25-Apr 00:10 bacula03-dir JobId 12490: console command: run BeforeJob
>> "prune expired volume yes"
>> 25-Apr 00:10 bacula03-dir JobId 12490: console command: run BeforeJob
>> "truncate allpools storage=FileStorage01"
>>
>> When I run these commands in bconsole there is always output.  Even if
>> it is just to say that there are no volumes to truncate, so I had
>> expected to see this output in the log under JobId 0. Is console 
>> command
>> output no logger logged from runscripts or am I missing something?
>>
>> Thanks
>>
>> Mike
>>
> I just got the 3 days worth of JobId 0 log entries in the log in one go, 
> including all the output I had expected from the prune expired and 
> truncate commands.
>
> 23-Apr 06:58 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 23-Apr 06:58 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 23-Apr 06:58 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 23-Apr 06:58 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 23-Apr 06:58 bacula03-dir JobId 0: No Volumes found to perform truncate 
> action.
> 23-Apr 06:58 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 23-Apr 06:58 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 23-Apr 06:58 bacula03-dir JobId 0: No Volumes found to perform truncate 
> action.
> 24-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 24-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 24-Apr 00:10 bacula03-dir JobId 0: The current Volume "IncPool-0109" 
> retention period is: 14 days
> 24-Apr 00:10 bacula03-dir JobId 0: There are no more Jobs associated 
> with Volume "IncPool-0109". Marking it purged.
> 24-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 24-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 24-Apr 00:10 bacula03-dir JobId 0: Connecting to Storage daemon 
> FileStorage01 at 192.168.42.45:9103 ...
> 24-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=212 DVD=0 
> Volume="IncPool-0109" Device="FileDevice01" (/bacula_storage/FileDevice)
> 24-Apr 00:10 bacula03-dir JobId 0: The volume "IncPool-0109" has been 
> truncated
> 24-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 24-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 24-Apr 00:10 bacula03-dir JobId 0: No Volumes found to perform truncate 
> action.
> 25-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 25-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 25-Apr 00:10 bacula03-dir JobId 0: The current Volume 
> "CatalogBackup0344" retention period is: 14 days
> 25-Apr 00:10 bacula03-dir JobId 0: There are no more Jobs associated 
> with Volume "CatalogBackup0344". Marking it purged.
> 25-Apr 00:10 bacula03-dir JobId 0: The current Volume 
> "CatalogBackup0242" retention period is: 14 days
> 25-Apr 00:10 bacula03-dir JobId 0: There are no more Jobs associated 
> with Volume "CatalogBackup0242". Marking it purged.
> 25-Apr 00:10 bacula03-dir JobId 0: The current Volume 
> "CatalogBackup0241" retention period is: 14 days
> 25-Apr 00:10 bacula03-dir JobId 0: There are no more Jobs associated 
> with Volume "CatalogBackup0241". Marking it purged.
> 25-Apr 00:10 bacula03-dir JobId 0: The current Volume "IncPool-0128" 
> retention period is: 14 days
> 25-Apr 00:10 bacula03-dir JobId 0: There are no more Jobs associated 
> with Volume "IncPool-0128". Marking it purged.
> 25-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 25-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 25-Apr 00:10 bacula03-dir JobId 0: Connecting to Storage daemon 
> FileStorage01 at 192.168.42.45:9103 ...
> 25-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=217 DVD=0 
> Volume="CatalogBackup0344" Device="FileDevice01" 
> (/bacula_storage/FileDevice)
> 25-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0344" has 
> been truncated
> 25-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=217 DVD=0 
> Volume="CatalogBackup0241" Device="FileDevice01" 
> (/bacula_storage/FileDevice)
> 25-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0241" has 
> been truncated
> 25-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=217 DVD=0 
> Volume="CatalogBackup0242" Device="FileDevice01" 
> (/bacula_storage/FileDevice)
> 25-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0242" has 
> been truncated
> 25-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=212 DVD=0 
> Volume="IncPool-0128" Device="FileDevice01" (/bacula_storage/FileDevice)
> 25-Apr 00:10 bacula03-dir JobId 0: The volume "IncPool-0128" has been 
> truncated
> 25-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog: 
> MyCatalog
> 25-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
> 25-Apr 00:10 bacula03-dir JobId 0: No Volumes found to perform truncate 
> action.
>
> I do not know what triggered it.  I was doing stuff in bconsole. I am 
> guessing that JobId 0 messages were being spooled until the job 
> "finished" and something I did "finished" it?  
It is quite likely that many of these messages are queued now Qmsg()
this means that they come out at the end of the job.  The reason for
queuing certain types of messages is to avoid race conditions that can
happen particularly when you do things like console commands inside
running jobs.  Normally queuing does not matter much except that the
messages are not in chronological order (annoying) but if you are trying
to see them in real-time while the job is running, it won't work.

Best regards,
Kern

> I do not think that this 
> was the behaviour in Bacula 5.x.
>
> Is this a bug or is there something that I am missing in my 
> configuration.
>
> Thanks
>
> Mike
>
> ------------------------------------------------------------------------------
> Start Your Social Network Today - Download eXo Platform
> Build your Enterprise Intranet with eXo Platform Software
> Java Based Open Source Intranet - Social, Extensible, Cloud Ready
> Get Started Now And Turn Your Intranet Into A Collaboration Platform
> http://p.sf.net/sfu/ExoPlatform
> _______________________________________________
> Bacula-users mailing list
> Bacula-users AT lists.sourceforge DOT net
> https://lists.sourceforge.net/lists/listinfo/bacula-users
>


------------------------------------------------------------------------------
Start Your Social Network Today - Download eXo Platform
Build your Enterprise Intranet with eXo Platform Software
Java Based Open Source Intranet - Social, Extensible, Cloud Ready
Get Started Now And Turn Your Intranet Into A Collaboration Platform
http://p.sf.net/sfu/ExoPlatform
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users