>>>>> On Thu, 1 Oct 2020 10:47:12 +0200, Radosław Korzeniewski said: > > Hello, > > I have an impression that you and I are talking about two totally > distinctive things, so to progress with our discussion all things have to > be cleared out. > > śr., 30 wrz 2020 o 14:04 <djosip+n...@linuxpages.net> napisał(a): > > > >> And indeed, messages in the second e-mail which correspond to the > > >> original Job seems to be sent by the Storage daemon. > > > > > > It is technically impossible as SD does not store job termination > > > status > > > messages for the original job. So it cannot send it to the user. These > > > messages are stored in the catalog and simply copied by the Director > > > during > > > copy job execution. > > > > Storage daemon sends it to the Director which sends it to the user > > after it combines the messages if it finds the corresponding Job IDs. > > > > Yes, it is true to some extent. > > > > > > The messages in the Catalog are not stored by the Storage daemon and > > as far as I know, they are not used for anything else but for manual > > browsing by some tools like BAT. > > > > > So, below is an example of the copied job log I have on hand: > > 2020-05-03 01:14:25 backup-dir JobId 167991: Start Backup JobId 167991, > Job=xxx.2020-05-03_01.00.00_30 > 2020-05-03 01:14:30 backup-dir JobId 167991: Using Device "File-Drive-01" to > write. > 2020-05-03 01:14:30 backup-dir JobId 167991: Using Volume "vol2292" from > 'Scratch' pool. > 2020-05-03 01:14:30 backup-dir JobId 167991: Recycled volume "vol2292" > 2020-05-03 01:14:35 backup-dir JobId 167991: Max Volume jobs=1 exceeded. > Marking Volume "vol2292" as Used. > 2020-05-03 01:14:35 backup-sd JobId 167991: Recycled volume "vol2292" on File > device "File-Drive-01" (/backup/volumes), all previous data lost. > 2020-05-03 01:14:37 backup-fd JobId 167991: Backup "xxx" (vm-240) start. > 2020-05-03 01:15:05 backup-fd JobId 167991: There are 2 disks. > 2020-05-03 01:15:05 backup-fd JobId 167991: create snapshot name > xxx.2020-05-03_01.00.00_30 succeeded. > 2020-05-03 01:28:16 backup-fd JobId 167991: Dump vmdk > 6000C294-0861-4dda-579d-9c3578e287d2 succeeded. > 2020-05-03 01:28:16 backup-fd JobId 167991: VDDK Transport "nbd" selected > 2020-05-03 01:28:35 backup-fd JobId 167991: Dump vmdk > 6000C29d-9771-8fc3-df55-61031caec345 succeeded. > 2020-05-03 01:28:35 backup-fd JobId 167991: VDDK Transport "nbd" selected > 2020-05-03 01:28:40 backup-dir JobId 167991: Bacula Enterprise backup-dir > 12.0.1 (02Jul19): > Build OS: x86_64-redhat-linux-gnu-bacula-enterprise redhat > Enterprise release > JobId: 167991 > Job: xxx.2020-05-03_01.00.00_30 > Backup Level: Full > Client: "xxx" 12.0.1 (02Jul19) > x86_64-redhat-linux-gnu-bacula-enterprise,redhat,Enterprise release > FileSet: "xxx" 2018-11-17 01:00:00 > Pool: "xxx" (From Job resource) > Catalog: "xxx" (From Client resource) > Storage: "backup-sd" (From Pool resource) > Scheduled time: 03-May-2020 01:00:00 > Start time: 03-May-2020 01:14:35 > End time: 03-May-2020 01:28:40 > Elapsed time: 14 mins 5 secs > Priority: 10 > FD Files Written: 8 > SD Files Written: 8 > FD Bytes Written: 17,544,329,232 (17.54 GB) > SD Bytes Written: 17,544,331,241 (17.54 GB) > Rate: 20762.5 KB/s > Software Compression: 42.6% 1.7:1 > Comm Line Compression: None > Snapshot/VSS: no > Encryption: no > Accurate: yes > Volume name(s): vol2292 > Volume Session Id: 507 > Volume Session Time: 1587987580 > Last Volume Bytes: 17,559,722,646 (17.55 GB) > Non-fatal FD errors: 0 > SD Errors: 0 > FD termination status: OK > SD termination status: OK > Termination: Backup OK > > 2020-05-03 01:28:40 backup-sd JobId 167991: Sending spooled attrs to the > Director. Despooling 2,350 bytes ... > 2020-05-03 01:28:40 backup-sd JobId 167991: Elapsed time=00:14:05, Transfer > rate=20.76 M Bytes/second > 2020-05-03 01:28:40 backup-fd JobId 167991: BACKUP OK xxx (vm-240) > 2020-05-03 01:28:40 backup-fd JobId 167991: Delete snapshot > xxx.2020-05-03_01.00.00_30 succeeded. > 2020-10-01 09:35:21 backup-dir JobId 177827: Using Device > "Cloud-xxx-Drive-01" to write. > 2020-10-01 09:35:22 backup-sd JobId 177827: Volume "cloud178569" previously > written, moving to end of data. > 2020-10-01 09:35:22 backup-sd JobId 177827: Using S3 cloud driver Host=xxx > Bucket=bacula > 2020-10-01 09:38:01 backup-sd JobId 177827: Elapsed time=00:02:39, Transfer > rate=110.3 M Bytes/second > 2020-10-01 09:38:01 backup-sd JobId 177827: Cloud Upload transfers: > 2020-10-01 09:38:04 backup-sd JobId 177827: cloud178569/part.6 state=done > size=1.073 GB duration=71s > 2020-10-01 09:39:55 backup-sd JobId 177827: cloud178569/part.7 state=done > size=1.073 GB duration=72s > 2020-10-01 09:41:18 backup-sd JobId 177827: cloud178569/part.8 state=done > size=1.073 GB duration=72s > 2020-10-01 09:42:46 backup-sd JobId 177827: cloud178569/part.9 state=done > size=1.073 GB duration=71s > 2020-10-01 09:43:57 backup-sd JobId 177827: cloud178569/part.10 state=done > size=1.073 GB duration=71s > 2020-10-01 09:46:06 backup-sd JobId 177827: cloud178569/part.11 state=done > size=1.073 GB duration=72s > 2020-10-01 09:47:33 backup-sd JobId 177827: cloud178569/part.12 state=done > size=1.073 GB duration=72s > 2020-10-01 09:48:44 backup-sd JobId 177827: cloud178569/part.13 state=done > size=1.073 GB duration=71s > 2020-10-01 09:50:45 backup-sd JobId 177827: cloud178569/part.14 state=done > size=1.073 GB duration=71s > 2020-10-01 09:52:23 backup-sd JobId 177827: cloud178569/part.15 state=done > size=1.073 GB duration=71s > 2020-10-01 09:54:01 backup-sd JobId 177827: cloud178569/part.16 state=done > size=1.073 GB duration=72s > 2020-10-01 09:55:13 backup-sd JobId 177827: cloud178569/part.17 state=done > size=1.073 GB duration=71s > 2020-10-01 09:56:24 backup-sd JobId 177827: cloud178569/part.18 state=done > size=1.073 GB duration=71s > 2020-10-01 09:58:25 backup-sd JobId 177827: cloud178569/part.19 state=done > size=1.073 GB duration=71s > 2020-10-01 10:00:16 backup-sd JobId 177827: cloud178569/part.20 state=done > size=1.073 GB duration=72s > 2020-10-01 10:01:27 backup-sd JobId 177827: cloud178569/part.21 state=done > size=1.073 GB duration=62s > 2020-10-01 10:01:53 backup-sd JobId 177827: cloud178569/part.22 state=done > size=379.9 MB duration=25s > 2020-10-01 10:01:53 backup-sd JobId 177827: Sending spooled attrs to the > Director. Despooling 2,350 bytes ... > > It is somehow combined from the two logs for the following jobids: 167991 - > which is an original backup job and 177827 - which is a copy job. I'm > unable to explain how the original jobid 167991 log was included, other > than it was just copied from the log table by Director and not SD. Any > thoughts here?
Yes, the original log table entries are just copied to the new job: https://www.bacula.org/git/cgit.cgi/bacula/tree/bacula/src/dird/mac.c?h=Branch-9.6#n724 They will not be in the email though. > > > > Storage daemon does not make a connection to the database, only > > Bacula Dir can do that. > > > > And this is a reason SD cannot copy the original log. > > Additionally, those logs in the Catalog are getting stored in the > > Catalog only in case one is using Postgres. In case of MySQL the log > > table is empty. > > I am currently using Postgres but when I used MySQL Bacula behaved > > exactly the same (in regard to the issue we are discussing here) > > except the log table was empty. > > > > I do not use MySQL for Bacula, so I cannot verify it. > > >> Here is the example of one such additional e-mail message: > > >> > > >> 30-Sep 06:18 bkp1-dir JobId 5132: Using Device "tape1-dev1" to write. > > >> 30-Sep 06:18 bkp1-sd JobId 5132: Spooling data ... > > >> 30-Sep 06:21 bkp1-sd JobId 5132: Committing spooled data to Volume > > >> "tapevol-0011". Despooling 901,424,162 bytes ... > > >> 30-Sep 06:21 bkp1-sd JobId 5132: Despooling elapsed time = 00:00:05, > > >> Transfer rate = 180.2 M Bytes/second > > >> 30-Sep 06:21 bkp1-sd JobId 5132: Elapsed time=00:02:16, Transfer > > >> rate=6.621 M Bytes/second > > >> 30-Sep 06:21 bkp1-sd JobId 5132: Sending spooled attrs to the > > >> Director. > > >> Despooling 580 bytes ... > > >> > > > > > > Is it an original job message or a copy job message? What job ids are > > > for > > > an original job and its clone? Could you check, please. You have to > > > distinguish between an original backup job message and message > > > generated during copy. > > > > The original (normal Full Backup) job ID was: 4997 > > > > I'm talking about logs from this job. > > > > The ID of the first Copy job which started the copy was 4999 > > The ID that actually copied JobID 4997 from disk to tape was 5132 > > > > which are combined with the above logs and saved as target logs. > > > > That Job 5132 was the one whose messages are getting sent in the > > separate e-mail message and I believe it would make more sense if > > its messages would be combined with the messages that belong to the > > job with the JobID 4999 which started it. > > > > Why? I do not understand. How many copy jobs do you copy on a single copy > job run? I think Josip wants a single email that combines the logs from the job that reads the old volume (the Copy job) and the job that writes to the new volume (the new Backup job). This would be like the single email that you get for a normal backup job, which combines messages from the FD (reading) with the SD (writing). __Martin _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
