[Bacula-bugs] [Bacula Bug Reports 0002232]: Include information in joblog (backup.c) and (restore.c

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

A NOTE has been added to this issue. 
====================================================================== 
http://bugs.bacula.org/view.php?id=2232 
====================================================================== 
Reported By:                wandihuttel
Assigned To:                
====================================================================== 
Project:                    Bacula Bug Reports
Issue ID:                   2232
Category:                   Director
Reproducibility:            always
Severity:                   minor
Priority:                   normal
Status:                     new
====================================================================== 
Date Submitted:             2016-07-05 11:04 BRT
Last Modified:              2016-07-18 22:10 BRT
====================================================================== 
Summary:                    Include information in joblog (backup.c) and
(restore.c)
Description: 
A information that I think is missing in joblog and is very helpful is the
"ReadBytes". 
With this information is easier to know the original backup size.

In restore.c I noticed that was missing the information "Elapsed Time", so I
include too.

So I've made a patch as suggested to include in src/dird/backup.c and
src/dird/restore.c.

Additional Information: 
JobLog after patches

***** Backup JobLog *****

2016-07-04 21:30:01   bacula-dir JobId 4881: Start Backup JobId 4881,
Job=Backup_Servidor_Firewall.2016-07-04_21.30.00_30
2016-07-04 21:30:01   bacula-dir JobId 4881: Using Device "DiscoLocal1" to
write.
2016-07-04 21:30:02   srv_firewall-fd JobId 4881: shell command: run
ClientBeforeJob "/usr/local/bin/backup_mysql_bacula.sh"
2016-07-04 21:30:02   srv_firewall-fd JobId 4881: ClientBeforeJob: Backing up
information_schema... Done.
2016-07-04 21:30:03   srv_firewall-fd JobId 4881: ClientBeforeJob: Backing up
db_admin... Done.
2016-07-04 21:30:03   srv_firewall-fd JobId 4881: ClientBeforeJob: Backing up
iptables... Done.
2016-07-04 21:31:04   srv_firewall-fd JobId 4881: ClientBeforeJob: Backing up
mysar... Done.
2016-07-04 21:31:07   srv_firewall-fd JobId 4881: ClientBeforeJob: Backing up
mysql... Done.
2016-07-04 21:32:49   bacula-sd JobId 4881: Elapsed time=00:01:42, Transfer
rate=3.745 M Bytes/second
2016-07-04 21:32:49   bacula-sd JobId 4881: Sending spooled attrs to the
Director. Despooling 129,087 bytes ...
2016-07-04 21:32:50   bacula-dir JobId 4881: Bacula bacula-dir 7.4.1 (02May16):
  Build OS:               x86_64-unknown-linux-gnu debian 8.4
  JobId:                  4881
  Job:                    Backup_Servidor_Firewall.2016-07-04_21.30.00_30
  Backup Level:           Differential, since=2016-07-01 19:31:07
  Client:                 "srv_firewall-fd" 7.4.0 (16Jan16)
x86_64-unknown-linux-gnu,debian,6.0.10
  FileSet:                "FileSet_SRV_Firewall" 2015-12-01 21:30:01
  Pool:                   "Diaria" (From Run Pool override)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "StorageLocal1" (From Pool resource)
  Scheduled time:         04-Jul-2016 21:30:00
  Start time:             04-Jul-2016 21:31:07
  End time:               04-Jul-2016 21:32:50
  Elapsed time:           1 min 43 secs
  Priority:               10
  FD Files Written:       401
  SD Files Written:       401
  FD Bytes Read:          2,233,641,040 (2.233 GB)
  FD Bytes Written:       382,037,550 (382.0 MB)
  SD Bytes Written:       382,088,825 (382.0 MB)
  Rate:                   3709.1 KB/s
  Software Compression:   82.9% 5.8:1
  Snapshot/VSS:           no
  Encryption:             no
  Accurate:               no
  Volume name(s):         Volume-Diario-0005
  Volume Session Id:      7
  Volume Session Time:    1467655758
  Last Volume Bytes:      1,220,626,290 (1.220 GB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK
2016-07-04 21:32:51   bacula-dir JobId 4881: Begin pruning Jobs older than 1
year .
2016-07-04 21:32:51   bacula-dir JobId 4881: No Jobs found to prune.
2016-07-04 21:32:51   bacula-dir JobId 4881: Begin pruning Files.
2016-07-04 21:32:51   bacula-dir JobId 4881: No Files found to prune.
2016-07-04 21:32:51   bacula-dir JobId 4881: End auto prune.
2016-07-04 21:32:51   bacula-dir JobId 4881: shell command: run AfterJob
"/etc/bacula/scripts/_send_telegram.sh 4881"

***** Restore JobLog *****

bacula-dir JobId 4826: Start Restore Job Restore_Files.2016-06-29_10.12.46_03
bacula-dir JobId 4826: Using Device "DiscoLocal1" to read.
bacula-sd JobId 4826: Ready to read from volume "Volume-Diario-0002" on file
device "DiscoLocal1" (/mnt/disco01).
bacula-sd JobId 4826: Forward spacing Volume "Volume-Diario-0002" to file:block
0:2197155592.
bacula-sd JobId 4826: Elapsed time=00:00:45, Transfer rate=11.67 M Bytes/second
bacula-dir JobId 4826: Bacula bacula-dir 7.4.1 (02May16):
  Build OS:               x86_64-unknown-linux-gnu debian 8.4
  JobId:                  4826
  Job:                    Restore_Files.2016-06-29_10.12.46_03
  Restore Client:         wanderlei-fd
  Start time:             29-Jun-2016 10:12:48
  End time:               29-Jun-2016 10:13:53
  Elapsed time:           1 min 5 secs
  Files Expected:         2
  Files Restored:         2
  Bytes Read:             525,530,904 (525.5 MB)
  Bytes Restored:         2,900,767,612 (2.900 GB)
  Rate:                   44627.2 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Restore OK

bacula-dir JobId 4826: Begin pruning Jobs older than 1 year .
bacula-dir JobId 4826: No Jobs found to prune.
bacula-dir JobId 4826: Begin pruning Files.
bacula-dir JobId 4826: No Files found to prune.
bacula-dir JobId 4826: End auto prune.
====================================================================== 

---------------------------------------------------------------------- 
 (0007365) kern (administrator) - 2016-07-17 11:37
 http://bugs.bacula.org/view.php?id=2232#c7365 
---------------------------------------------------------------------- 
I think the idea is good, but I have some problems.  Including the bytes read in
the Backup report will probably create a lot of support questions, because in
the case of a Differential backup such as what you show, these are not really
bytes read but rather the total size of files that were examined for backup --
or the size a Full would have.  Though it is a useful figure to see, I believe
that it will create a lot of confusion and thus as mentioned above support
questions.

For the restore: there is clearly something wrong.  Your bytes read is smaller
than the bytes restored.  In fact, the FD did not read any bytes, it simply did
a restore, so this too will create a lot of support questions.

At this point, I am not sure these patches should be applied.  

What do you (or others) think? 

---------------------------------------------------------------------- 
 (0007367) wandihuttel (reporter) - 2016-07-17 22:17
 http://bugs.bacula.org/view.php?id=2232#c7367 
---------------------------------------------------------------------- 
I don't know if it will impact on support issues, perhaps the title is not the
best that I chose (another suggestion?).
I know the ReadBytes is the total size of files that were examined for backup,
but when it uses compression, I understood that FD writes less bytes than it
reads, because bacula already writes data compressed.

And about restore I guess is not wrong because when data is compressed, bacula
reads the data from the SD (compressed data, less bytes) and restore the entire
data to a client (uncompressed data, more bytes)

The main goal is to show the original size of files of any job in joblog. 

---------------------------------------------------------------------- 
 (0007370) wandihuttel (reporter) - 2016-07-18 22:10
 http://bugs.bacula.org/view.php?id=2232#c7370 
---------------------------------------------------------------------- 
Hello Kern. How I enabled accurate=pins5 in my filesets, I saw that the
ReadBytes is not that I though, it looks that reads the entire folders and the
size of ReadBytes is totally different of the size of files were examined for
backup. Sorry I was wrong. 
But I guess is possible to include the information about "original job size"
calculating the job size reverting % of data compressing. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2016-07-05 11:04 wandihuttel    New Issue                                    
2016-07-05 11:04 wandihuttel    File Added: backup.c.patch                    
2016-07-05 11:05 wandihuttel    File Added: restore.c.patch                    
2016-07-17 11:37 kern           Note Added: 0007365                          
2016-07-17 11:37 kern           Status                   new => feedback     
2016-07-17 22:17 wandihuttel    Note Added: 0007367                          
2016-07-17 22:17 wandihuttel    Status                   feedback => new     
2016-07-18 22:10 wandihuttel    Note Added: 0007370                          
======================================================================

[Bacula-bugs] [Bacula Bug Reports 0002232]: Include information in joblog (backup.c) and (restore.c

[Bacula-bugs] [Bacula Bug Reports 0002232]: Include information in joblog (backup.c) and (restore.c)