On 04/25/2014 10:07 PM, Brady, Mike wrote:
> On 2014-04-25 11:13, Brady, Mike wrote:
>> On 2014-04-25 09:17, Kern Sibbald wrote:
>>> 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
>>>>
>> I was not trying to view the messages in real time while the job was
>> running. The BackupCatalog job is scheduled to run at 0010 every day.
>> All the messages for that BackupCatalog JobId are logged/emailed as
>> expected when the job completes. I was looking at the logs after the
>> fact.
>>
>> The full output from last nights BackupCatalog job is below.
>>
>> ============ BEGIN LOG ======================
>> 25-Apr 00:10 bacula03-dir JobId 12490: shell command: run BeforeJob
>> "/usr/libexec/bacula/make_catalog_backup.pl MyCatalog"
>> 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"
>> 25-Apr 00:10 bacula03-dir JobId 12490: console command: run BeforeJob
>> "truncate allpools storage=FileStorage02"
>> 25-Apr 00:10 bacula03-dir JobId 12490: Start Backup JobId 12490,
>> Job=BackupCatalog.2014-04-25_00.10.00_28
>> 25-Apr 00:10 bacula03-dir JobId 12490: Using Device "FileDevice01" to
>> write.
>> 25-Apr 00:10 bacula03-sd JobId 12490: Volume "CatalogBackup0243"
>> previously written, moving to end of data.
>> 25-Apr 00:10 bacula03-sd JobId 12490: Ready to append to end of Volume
>> "CatalogBackup0243" size=422,687,066
>> 25-Apr 00:10 bacula03-sd JobId 12490: Elapsed time=00:00:06, Transfer
>> rate=4.214 M Bytes/second
>> 25-Apr 00:10 bacula03-dir JobId 12490: Bacula bacula03-dir 7.0.2
>> (02Apr14):
>> Build OS: x86_64-redhat-linux-gnu redhat Enterprise
>> release
>> JobId: 12490
>> Job: BackupCatalog.2014-04-25_00.10.00_28
>> Backup Level: Full
>> Client: "bacula03-fd" 7.0.2 (02Apr14)
>> x86_64-redhat-linux-gnu,redhat,Enterprise release
>> FileSet: "Catalog" 2012-07-31 23:10:00
>> Pool: "CatalogBackupPool" (From Job resource)
>> Catalog: "MyCatalog" (From Client resource)
>> Storage: "FileStorage01" (From Job resource)
>> Scheduled time: 25-Apr-2014 00:10:00
>> Start time: 25-Apr-2014 00:10:05
>> End time: 25-Apr-2014 00:10:11
>> Elapsed time: 6 secs
>> Priority: 11
>> FD Files Written: 1
>> SD Files Written: 1
>> FD Bytes Written: 25,286,874 (25.28 MB)
>> SD Bytes Written: 25,286,991 (25.28 MB)
>> Rate: 4214.5 KB/s
>> Software Compression: 67.9% 3.1:1
>> VSS: no
>> Encryption: no
>> Accurate: no
>> Volume name(s): CatalogBackup0243
>> Volume Session Id: 317
>> Volume Session Time: 1397354160
>> Last Volume Bytes: 448,003,057 (448.0 MB)
>> Non-fatal FD errors: 0
>> SD Errors: 0
>> FD termination status: OK
>> SD termination status: OK
>> Termination: Backup OK
>>
>> 25-Apr 00:10 bacula03-dir JobId 12490: shell command: run AfterJob
>> "/usr/libexec/bacula/delete_catalog_backup"
>> ========== END LOG ======================
>>
>> There is no output for the runscript console commands associated with
>> this job or the previous nights jobs.
>>
>> The JobId 0 log output in my previous email was all written to the log
>> at 0745 25 April 2014 in one go. That is output for the 3 previous
>> nights jobs all together. It was a direct cut and paste from the log.
>> I did not remove any lines. At 0745 I was in bconsole doing stuff. I
>> wasn't watching the log at the time so I am not sure exactly what it
>> was
>> that I did to trigger the output. I am guessing that console command
>> messages are not coming through because they are going against JobId 0
>> (not the BackupCatalog jobid) and that JobId 0 is not completing so the
>> messages are never sent?
>>
>> In 5.2 the runscript console commands were logged at the "same" time of
>> the job. Looking at some logs from a couple of weeks ago they look
>> like
>> they were always logged before the messages from the job that had the
>> runscript in them, which is not a problem. The important thing is that
>> they are in the log. An example is below.
>>
>> =========== BEGIN LOG ======================
>> 11-Apr 00:10 bacula03-dir JobId 0:
>> This command can be DANGEROUS!!!
>>
>> It purges (deletes) all Files from a Job,
>> JobId, Client or Volume; or it purges (deletes)
>> all Jobs from a Client or Volume without regard
>> to retention periods. Normally you should use the
>> PRUNE command, which respects retention periods.
>> 11-Apr 00:10 bacula03-dir JobId 0: Automatically selected Catalog:
>> MyCatalog
>> 11-Apr 00:10 bacula03-dir JobId 0: Using Catalog "MyCatalog"
>> 11-Apr 00:10 bacula03-dir JobId 0: Connecting to Storage daemon
>> FileStorage01 at 192.168.42.45:9103 ...
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0165" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0165" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0098" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0098" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0062" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0062" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0289" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0289" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0103" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0103" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0097" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0097" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0042" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0042" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0138" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0138" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0052" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0052" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0290" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0290" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0269" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0269" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0113" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0113" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0175" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0175" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0185" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0185" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 0: 3000 OK label. VolBytes=219 DVD=0
>> Volume="CatalogBackup0270" Device="FileDevice01"
>> (/bacula_storage/FileDevice)
>> 11-Apr 00:10 bacula03-dir JobId 0: The volume "CatalogBackup0270" has
>> been truncated
>> 11-Apr 00:10 bacula03-dir JobId 12100: shell command: run BeforeJob
>> "/usr/libexec/bacula/make_catalog_backup.pl MyCatalog"
>> 11-Apr 00:10 bacula03-dir JobId 12100: Start Backup JobId 12100,
>> Job=BackupCatalog.2014-04-11_00.10.00_38
>> 11-Apr 00:10 bacula03-dir JobId 12100: Recycled volume
>> "CatalogBackup0243"
>> 11-Apr 00:10 bacula03-dir JobId 12100: Using Device "FileDevice01" to
>> write.
>> 11-Apr 00:10 bacula03-sd JobId 12100: Recycled volume
>> "CatalogBackup0243" on device "FileDevice01"
>> (/bacula_storage/FileDevice), all previous data lost.
>> 11-Apr 00:10 bacula03-sd JobId 12100: Elapsed time=00:00:05, Transfer
>> rate=4.875 M Bytes/second
>> 11-Apr 00:10 bacula03-dir JobId 12100: Bacula bacula03-dir 5.2.13
>> (19Jan13):
>> Build OS: x86_64-redhat-linux-gnu redhat Enterprise
>> release
>> JobId: 12100
>> Job: BackupCatalog.2014-04-11_00.10.00_38
>> Backup Level: Full
>> Client: "bacula03-fd" 5.2.13 (19Jan13)
>> x86_64-redhat-linux-gnu,redhat,Enterprise release
>> FileSet: "Catalog" 2012-07-31 23:10:00
>> Pool: "CatalogBackupPool" (From Job resource)
>> Catalog: "MyCatalog" (From Client resource)
>> Storage: "FileStorage01" (From Job resource)
>> Scheduled time: 11-Apr-2014 00:10:00
>> Start time: 11-Apr-2014 00:10:05
>> End time: 11-Apr-2014 00:10:10
>> Elapsed time: 5 secs
>> Priority: 11
>> FD Files Written: 1
>> SD Files Written: 1
>> FD Bytes Written: 24,377,895 (24.37 MB)
>> SD Bytes Written: 24,378,012 (24.37 MB)
>> Rate: 4875.6 KB/s
>> Software Compression: 67.8 %
>> VSS: no
>> Encryption: no
>> Accurate: no
>> Volume name(s): CatalogBackup0243
>> Volume Session Id: 112
>> Volume Session Time: 1396657274
>> Last Volume Bytes: 24,406,180 (24.40 MB)
>> Non-fatal FD errors: 0
>> SD Errors: 0
>> FD termination status: OK
>> SD termination status: OK
>> Termination: Backup OK
>>
>> 11-Apr 00:10 bacula03-dir JobId 12100: shell command: run AfterJob
>> "/usr/libexec/bacula/delete_catalog_backup"
>> 11-Apr 00:10 bacula03-dir JobId 12100: console command: run AfterJob
>> "purge volume action=all allpools storage=FileStorage01"
>> ============= END LOG ====================
>>
>> Thanks for your help.
>>
>> Mike
>>
> Running the reload command in bconsole is what causes the JobId 0
> messages to be written to the log.
>
> I can easily recreate this by running my BackupCatalog job (which has
> the console commands in it), waiting for it finish and write its log
> entries and then running the reload.
>
> Is this a bug or am I doing something wrong?
I believe that I have fixed this. Try the Bacula version that is in the
public repository. I hope to release it next week (possibly the week
after) as 7.0.3. If it still fails, and I can find out why, there is a
good chance I can fix it.
Kern
>
> 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@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/bacula-users
>
------------------------------------------------------------------------------
"Accelerate Dev Cycles with Automated Cross-Browser Testing - For FREE
Instantly run your Selenium tests across 300+ browser/OS combos. Get
unparalleled scalability from the best Selenium testing platform available.
Simple to use. Nothing to install. Get started now for free."
http://p.sf.net/sfu/SauceLabs
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
