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