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? > 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? > > They ended in the approximately the same time: 06:21 > Prev Backup JobId: 4997 > This job was running a way ahead of the below's copy jobs, right? > New Backup JobId: 5132 > Current JobId: 4999 > which is ok. > > That job was the last one so I have checked another one just to check > that everything looks as it should because the Copy job with the ID > of 4997 is the first Copy job which also processes he Selection Type > directive from the Job configuration. > > So, the IDs of another job: > The original (normal Full Backup) job ID was: 4996 > The ID of the first Copy job which started the copy was 5130 > The ID that actually copied JobID 4997 from disk to tape was 5131 > > They ended in the approximatelly the same time: 06:18 > In the message it says: > Prev Backup JobId: 4996 > New Backup JobId: 5131 > Current JobId: 5130 > which all correct and expected. > There is a need for a deep redesign of the main Bacula components and if you have an idea how it should work just discuss it on the devel list. best regards -- Radosław Korzeniewski rados...@korzeniewski.net
_______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
