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