On 2014-05-05 00:41, Kern Sibbald wrote:
> 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 Kern. I will have a look at this when 7.0.3 is released and will
let you know.
------------------------------------------------------------------------------
Is your legacy SCM system holding you back? Join Perforce May 7 to find out:
• 3 signs your SCM is hindering your productivity
• Requirements for releasing software faster
• Expert tips and advice for migrating your SCM now
http://p.sf.net/sfu/perforce
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
