View Issue Details

IDProjectCategoryView StatusLast Update
0000605bareos-coredirectorpublic2016-01-21 10:44
ReporterdanielAssigned Topstorz  
PriorityhighSeveritymajorReproducibilityalways
Status closedResolutionno change required 
PlatformLinuxOSDebianOS Version8
Product Version15.2.2 
Summary0000605: VirtualFull joblog Start/End/Elpase Informations are wrong in database and also in the log
DescriptionThe job informations Start Time, End Time and Elapsed Time for jobs with the Level VirtuallFull are always wrong.

The Start and End Time information are in the past and the range is also to short which leads into a fales "Elapsed Time". The wrong times have no pattern, their a sometimes a day behind or only 2 hours.

This leads into variant issues which are mostly related to display (sorting in lists) errors.
Steps To ReproducePerform VirtualFull
Additional InformationDatabase: Postgresql
Real Start Time: 2016-01-19_14.32.41_07
Real End Time: 2016-01-19 16:15:53

 2016-01-19 16:15:53 bareos1-dir JobId 8088: Bareos bareos1-dir 15.2.2 (16Nov15):
  Build OS: x86_64-pc-linux-gnu debian Debian GNU/Linux 8.0 (jessie)
  JobId: 8088
  Job: katzenklo02.rz.2016-01-19_14.32.41_07
  Backup Level: Virtual Full
  Client: "katzenklo02.rz.example.de" 14.2.5 (27May15) Microsoft Windows 8 Enterprise Edition (build 9200), 64-bit,Cross-compile,Win64
  FileSet: "katzenklo02.rz-fs1" 2015-08-07 16:00:02
  Pool: "VFBP" (From Job Pool's NextPool resource)
  Catalog: "MyCatalog" (From Client resource)
  Storage: "VirtualStorageVFB" (From Storage from Pool's NextPool resource)
  Scheduled time: 19-Jan-2016 14:32:29
  Start time: 19-Jan-2016 12:10:44
  End time: 19-Jan-2016 12:12:48
  Elapsed time: 2 mins 4 secs
  Priority: 10
  SD Files Written: 13,339
  SD Bytes Written: 73,279,488,824 (73.27 GB)
  Rate: 590963.6 KB/s
  Volume name(s): VFBP-1255|VFBP-1263|VFBP-1265|VFBP-1278|VFBP-1273|VFBP-1280|VFBP-1272|VFBP-3489|VFBP-1283
  Volume Session Id: 44
  Volume Session Time: 1452894697
  Last Volume Bytes: 4,586,626,448 (4.586 GB)
  SD Errors: 0
  SD termination status: OK
  Termination: Backup OK

2016-01-19 16:15:53 bareos1-dir JobId 8088: shell command: run AfterJob "/usr/local/lib/bareos/scripts/contact_user.pl --jobid=8088 --client=katzenklo02.rz.example.de
--verbose"
 2016-01-19 16:15:54 bareos1-dir JobId 8088: AfterJob: Get Description for Client 'katzenklo02.rz.example.de': 'Hans Wurst;hans.wurst@example.de;3;Windows User PC'
 2016-01-19 16:15:54 bareos1-dir JobId 8088: AfterJob: No status email necessary! Skript /usr/local/lib/bareos/scripts/contact_user.pl finished with 0.1s cputime.
TagsNo tags attached.

Activities

Shodan

Shodan

2016-01-20 10:13

reporter   ~0002118

It seems that Bareos MySQL database return zero on statement

ld4-bar-dir-01 (15): bvfs.c:798-0 q=SELECT 'F', T1.PathId, T1.FilenameId, Filename.Name, File.JobId, File.LStat, File.FileId FROM Job, File, ( SELECT MAX(JobTDate) AS JobTDate, PathId, FilenameId FROM ( SELECT JobTDate, PathId, FilenameId FROM File JOIN Job USING (JobId) WHERE File.JobId IN (17925,28325) AND PathId = 0 UNION ALL SELECT JobTDate, PathId, FilenameId FROM BaseFiles JOIN File USING (FileId) JOIN Job ON (BaseJobId = Job.JobId) WHERE BaseFiles.JobId IN (17925,28325) AND PathId = 0 ) AS tmp GROUP BY PathId, FilenameId LIMIT 2000 OFFSET 0) AS T1 JOIN Filename USING (FilenameId) WHERE T1.JobTDate = Job.JobTDate AND Job.JobId = File.JobId AND T1.PathId = File.PathId AND T1.FilenameId = File.FilenameId AND Filename.Name != '' AND File.FileIndex > 0 AND (Job.JobId IN ( SELECT DISTINCT BaseJobId FROM BaseFiles WHERE JobId IN (17925,28325)) OR Job.JobId IN (17925,28325))

With "PathId = 0", the statement always returns null value.
daniel

daniel

2016-01-20 10:20

reporter   ~0002119

Shodan your note is in the wrong ticket i guess?
mvwieringen

mvwieringen

2016-01-20 16:00

developer   ~0002125

I had a look at the vbackup code and it seems this is by design.
e.g. it copies back the data from the last previous Job e.g.

   /*
    * Update final items to set them to the previous job's values
    */
   Mmsg(query, "UPDATE Job SET StartTime='%s',EndTime='%s',"
               "JobTDate=%s WHERE JobId=%s",
        jcr->previous_jr.cStartTime, jcr->previous_jr.cEndTime,
        edit_uint64(jcr->previous_jr.JobTDate, ec1),
        edit_uint64(jcr->JobId, ec2));
pstorz

pstorz

2016-01-21 10:44

administrator   ~0002134

The timestamps need to be set to the ones of the last backup that was consolidated, as the new Full Backup can be the base for incremental or differential backups.

In order to not skip files that were created between the last backup that was consolidated and the virtual full backup run itself, the timestamp needs to be set as it is being set.

Issue History

Date Modified Username Field Change
2016-01-20 10:07 daniel New Issue
2016-01-20 10:13 Shodan Note Added: 0002118
2016-01-20 10:16 daniel Additional Information Updated
2016-01-20 10:20 daniel Note Added: 0002119
2016-01-20 16:00 mvwieringen Note Added: 0002125
2016-01-21 10:44 pstorz Note Added: 0002134
2016-01-21 10:44 pstorz Status new => closed
2016-01-21 10:44 pstorz Assigned To => pstorz
2016-01-21 10:44 pstorz Resolution open => no change required