Re: [Bacula-users] Message resource when copying jobs

Hello Christoph,

You're right, the mail messages are about the new backup job that writes data from the previous job(s)/volume(s) to the new job(s)/volume(s).

From: Bacula <bacula AT uni-koblenz DOT de>
To: bacula AT uni-koblenz DOT de
Subject: Bacula: Backup OK of clientname Incremental

02-Oct 05:09 bacula-dir JobId 697689: Using Device "LTO4-0" to write.
02-Oct 05:09 bacula-sd JobId 697689: Elapsed time=00:00:04, Transfer rate=89.96 M Bytes/second
02-Oct 05:09 bacula-sd JobId 697689: Sending spooled attrs to the Director. Despooling 26,284 bytes …

The above three messages are from director and storage daemon:

src/dird/msgchan.c
    348       if (ok) {
    349          Jmsg(jcr, M_INFO, 0, _("Using Device \"%s\" to write.\n"), device_name.c_str());
    350       }

src/stored/append.c
    341    Jmsg(dcr->jcr, M_INFO, 0, _("Elapsed time=%02d:%02d:%02d, Transfer rate=%s Bytes/second\n"),
    342          job_elapsed / 3600, job_elapsed % 3600 / 60, job_elapsed % 60,
    343          edit_uint64_with_suffix(jcr->JobBytes / job_elapsed, ec));

src/stored/spool.c:
    715       jcr->sendJobStatus(JS_AttrDespooling);
    716       Jmsg(jcr, M_INFO, 0, _("Sending spooled attrs to the Director. Despooling %s bytes ...\n"),
    717             edit_uint64_withsrc/stored/append.c_commas(size, ec1));

And it is possible that various other messages could be logged for this new backup job, like the bellow:

07-Oct 23:40 bacula-server-dir JobId 3: Created new Volume="WritePool-0002", Pool="WritePool", MediaType="File2" in catalog.
...

07-Oct 23:40 bacula-server-sd JobId 3: Labeled new Volume "WritePool-0002" on file device "FileChgr2-Dev1" (/opt/bacula/disks/disk2).
07-Oct 23:40 bacula-server-sd JobId 3: Wrote label to prelabeled Volume "WritePool-0002" on file device "FileChgr2-Dev1" (/opt/bacula/disks/disk2)

So, there will be a lot of code that will log this messages for the new backup job and not for the copy job.

Maybe this could be solved by setting wjcr->jcr_msgs = jcr->jcr_msgs in src/dird/mac.c. This way, all the messages from the new backup job (wjcr), would be treated by the same message resource as the Copy/Migration job.

I'm not sure about which approach would be better for debugging issues with copy and migrate jobs.

I'm also sending this message to the bacula-devel for appreciation.

Best regards,

Ana

On Mon, Oct 5, 2015 at 9:23 AM, Christoph Litauer <litauer AT uni-koblenz DOT de> wrote:

Hello Ana,

thanks for your response.

No, I defined three CopyJobs (Full, Diff and Incremental). All of them have Message = "TapeCopy":

Job {
Name = "CopyFull"
Type = Copy
Messages = TapeCopy
Pool = Full
Selection Type = PoolUncopiedJobs
Priority = 10
Schedule = Weekdays
Max Start Delay = 43200 # wait max 12 hours
Enabled = yes
Level = Full
Client = bacula
}

The mail body is logged in /var/log/bacula/bacula.log, too. But not in copy.log. copy.log instead has all other messages of the copy job, e.g.:

02-Oct 05:00 bacula-dir JobId 697688: Copying using JobId=697586 Job=holmes.2015-10-02_00.07.00_21
02-Oct 05:00 bacula-dir JobId 697688: Bootstrap records written to /var/bacula/bacula-dir.restore.10.bsr
02-Oct 05:09 bacula-dir JobId 697688: Start Copying JobId 697688, Job=CopyIncr.2015-10-02_05.00.03_04
02-Oct 05:09 bacula-dir JobId 697688: Using Device "FileStorage0" to read.
02-Oct 05:09 bacula-sd JobId 697688: 3307 Issuing autochanger "unload slot 1415, drive 0" command.
02-Oct 05:09 bacula-sd JobId 697688: 3304 Issuing autochanger "load slot 2436, drive 0" command.
02-Oct 05:09 bacula-sd JobId 697688: 3305 Autochanger "load slot 2436, drive 0", status is OK.
02-Oct 05:09 bacula-sd JobId 697688: Ready to read from volume "File-2436" on file device "FileStorage0" (/storage/changer/drive0).
02-Oct 05:09 bacula-sd JobId 697688: Forward spacing Volume "File-2436" to file:block 4:4182819019.
02-Oct 05:09 bacula-sd JobId 697688: End of Volume at file 4 on device "FileStorage0" (/storage/changer/drive0), Volume "File-2436"
02-Oct 05:09 bacula-sd JobId 697688: 3307 Issuing autochanger "unload slot 2436, drive 0" command.
02-Oct 05:09 bacula-sd JobId 697688: 3304 Issuing autochanger "load slot 2126, drive 0" command.
02-Oct 05:09 bacula-sd JobId 697688: 3305 Autochanger "load slot 2126, drive 0", status is OK.
02-Oct 05:09 bacula-sd JobId 697688: Ready to read from volume "File-2126" on file device "FileStorage0" (/storage/changer/drive0).
02-Oct 05:09 bacula-sd JobId 697688: Forward spacing Volume "File-2126" to file:block 0:196.
02-Oct 05:09 bacula-sd JobId 697688: End of Volume at file 0 on device "FileStorage0" (/storage/changer/drive0), Volume "File-2126"
02-Oct 05:09 bacula-sd JobId 697688: End of all volumes.
02-Oct 05:09 bacula-sd JobId 697688: Elapsed time=00:00:04, Transfer rate=89.96 M Bytes/second
02-Oct 05:09 bacula-dir JobId 697688: Bacula bacula-dir 7.2.0 (14Aug15):
Build OS: x86_64-suse-linux-gnu suse 12
Prev Backup JobId: 697586
Prev Backup Job: holmes.2015-10-02_00.07.00_21
New Backup JobId: 697689
Current JobId: 697688
Current Job: CopyIncr.2015-10-02_05.00.03_04
Backup Level: Full
Client: bacula
FileSet: "client files-to-backup" 2007-04-18 16:16:43
Read Pool: "Incr" (From Command input)
Read Storage: "DiskChanger" (From Pool resource)
Write Pool: "LTOincr" (From Command input)
Write Storage: "Scalar50" (From Command input)
Catalog: "MyCatalog" (From Client resource)
Start time: 02-Oct-2015 05:09:01
End time: 02-Oct-2015 05:09:06
Elapsed time: 5 secs
Priority: 10
SD Files Written: 112
SD Bytes Written: 359,861,747 (359.8 MB)
Rate: 71972.4 KB/s
Volume name(s): LTO4-053
Volume Session Id: 112
Volume Session Time: 1443691351
Last Volume Bytes: 179,426,806,784 (179.4 GB)
SD Errors: 0
SD termination status: OK
Termination: Copying OK

> Am 02.10.2015 um 19:21 schrieb Ana Emília M. Arruda <emiliaarruda AT gmail DOT com>:
>
> Hello Christoph,
>
> How is your job copy "messages" directive defined? It seems it is configured as "messages = Standard". Could you check if the text of this e-mail appears in /var/log/bacula/bacula.log or /var/log/bacula/copy.log?
>
> Best regards,
> Ana
>
> On Fri, Oct 2, 2015 at 9:22 AM, Christoph Litauer <litauer AT uni-koblenz DOT de> wrote:
> Dear bacula users,
>
> I recently upgraded from 5.1.3 to 7.2.0.
> Runs like a charm except for one thing:
> We do copy jobs every morning to copy the disk backups to tape. Every copy job sends a mail reporting "Backup OK of clientname incremental". Never had this in 5.1.3.
> My message ressources are:
>
> Messages {
> Name = Standard
> mailcommand = "/usr/bin/mail -r \"Bacula \<%r\>\" -s \"Bacula: %t %e of %c %l\" %r"
> operatorcommand = "/usr/bin/mail -r \"Bacula \<%r\>\" -s \"Bacula: Intervention needed for %j\" %r"
> mail = bacula at uni-koblenz.de = all, !skipped, !restored
> operator = litauer at uni-koblenz.de = mount
> console = all, !skipped, !saved, !restored
> catalog = all, !skipped, !saved
> append = "/var/log/bacula/bacula.log" = all, !skipped, !restored
> }
>
> Messages {
> Name = TapeCopy
> mailcommand = "/usr/bin/mail -r \"Bacula \<%r\>\" -s \"Bacula tape copy\" %r"
> operatorcommand = "/usr/bin/mail -r \"Bacula \<%r\>\" -s \"Bacula: Intervention needed for %j\" %r"
> Mail On Error = litauer AT uni-koblenz DOT de = all, !skipped
> operator = litauer AT uni-koblenz DOT de = mount
> append = "/var/log/bacula/copy.log" = all, !skipped
> }
>
> Example mail when a copy job is run:
> --------------------------------------------------------
> From: Bacula <bacula AT uni-koblenz DOT de>
> To: bacula AT uni-koblenz DOT de
> Subject: Bacula: Backup OK of clientname Incremental
>
> 02-Oct 05:09 bacula-dir JobId 697689: Using Device "LTO4-0" to write.
> 02-Oct 05:09 bacula-sd JobId 697689: Elapsed time=00:00:04, Transfer rate=89.96 M Bytes/second
> 02-Oct 05:09 bacula-sd JobId 697689: Sending spooled attrs to the Director. Despooling 26,284 bytes …
> ————————————————————————————
>
> I understand that a copy job in fact is a combined restore and backup job. But wouldn't it be enough to only get the copy job status?
>
> --
> Kind regards
> Christoph
> _________________________________________
> Christoph Litauer
> Uni Koblenz, Computing Centre, Office A 022
> Postfach 201602, 56016 Koblenz
> Fon: +49 261 287-1311, Fax: -100 1311
>
>
>
>
> ------------------------------------------------------------------------------
> _______________________________________________
> Bacula-users mailing list
> Bacula-users AT lists.sourceforge DOT net
> https://lists.sourceforge.net/lists/listinfo/bacula-users
>

--
Freundliche Grüße
Christoph Litauer
_________________________________________
Christoph Litauer
Uni Koblenz, Rechenzentrum, Raum A 022

Postfach 201602, 56016 Koblenz
Fon: +49 261 287-1311, Fax: -100 1311

------------------------------------------------------------------------------

_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users