Menu
▾
▴
[Bacula-bugs] [Bacula Bug Reports 0001979]: bacula vss windows verify job file count mismatch
|
From: Mantis B. T. <no...@bu...> - 2014-02-14 13:53:02
|
Issue 0001979 is now monitored by user windwalker78. ====================================================================== http://bugs.bacula.org/view.php?id=1979 ====================================================================== Reported By: angeloio Assigned To: ====================================================================== Project: Bacula Bug Reports Issue ID: 1979 Category: File Daemon Reproducibility: always Severity: minor Priority: normal Status: feedback ====================================================================== Date Submitted: 2013-01-15 16:24 GMT Last Modified: 2014-02-14 13:52 GMT ====================================================================== Summary: bacula vss windows verify job file count mismatch Description: director and storage daemon on debian 6 (5.2.6+dfsg-1~b); file daemon on windows 2008 r2 standard 64 sp1. if you enable VSS options for backup the verify job fails because the file number verified by the verify job mismatch respect the numebre of file backed up. Steps to Reproduce: a) enable Windows VSS for backup of e.g. 3 files on Windows daemon. Backup complete succefully with backup of 4 file! I can see with trace enabled a GUID added to backup for snapshot VSS pourposes. b) launch verify on that job: b1) the verify type volume-to-catalog fail cause number of files is mismatch, (minus one): file expected 4, file verified 3. b2) launch verify type disk-to-catalog end with warnings, but the number of file verified is always zero! Additional Information: This issue does not occur with VSS disabled; with Windows 2008 R2 Enterprise. In the catalog the informations about the file related to the guid are NOT present. This issue occur even with bacula director version on 5.0.2 This issue occur even with bacula windows 5.0.2, 5.2.5 and 5.2.5. ====================================================================== ---------------------------------------------------------------------- (0006610) kern (administrator) - 2013-02-15 21:29 http://bugs.bacula.org/view.php?id=1979#c6610 ---------------------------------------------------------------------- This appears to be a support problem, and nothing you report seems abnormal to me. So that I can be sure, please upload your FileSet resource, then after the backup, run a restore menu item 5 and do "mark *" then "lsmark". I suspect that you will find that four "files" were backed up. Please include the complete output from running those commands. ---------------------------------------------------------------------- (0006688) Steve Lee (reporter) - 2013-05-01 22:30 http://bugs.bacula.org/view.php?id=1979#c6688 ---------------------------------------------------------------------- I have the same error Running Bacula 5.2.6 on Linux version 3.5.0-22 Client running on bacula-win64-5.2.10 on Windows Server 2008 (SP1) We recently added verify jobs to our schedule and have noticed that one of the jobs always fails. it shows a mismatch between expected and examined files. Files Expected: 2 Files Examined: 1 The backup job itself reports 2 files backed up FD Files Written: 2 SD Files Written: 2 Running queries against the catalog... Enter SQL query: select jobfiles from job where jobid = 988; +----------+ | jobfiles | +----------+ | 2 | +----------+ Enter SQL query: select count(*) from file where jobid =988; +-------+ | count | +-------+ | 1 | +-------+ The fileset contains a single file FileSet { Name = "zmail-delta" Include { Options { signature = MD5 compression = GZIP aclsupport = yes } File = "E:/WindowsImageBackup.delta" } } ---------------------------------------------------------------------- (0006689) Steve Lee (reporter) - 2013-05-01 22:34 http://bugs.bacula.org/view.php?id=1979#c6689 ---------------------------------------------------------------------- Output from running lsmark $ ls E:/ $ mark * 2 files marked. $ lsmark *E:/ *WindowsImageBackup.delta $ ---------------------------------------------------------------------- (0006690) martin (reporter) - 2013-05-02 11:50 http://bugs.bacula.org/view.php?id=1979#c6690 ---------------------------------------------------------------------- I think it is caused by the job_metadata.xml object, which is not the file table. ---------------------------------------------------------------------- (0006691) Steve Lee (reporter) - 2013-05-05 08:06 http://bugs.bacula.org/view.php?id=1979#c6691 ---------------------------------------------------------------------- I reran with Enable VSS = no and this time the verify job worked FD Files Written: 1 SD Files Written: 1 Files Expected: 1 Files Examined: 1 Enter SQL query: select jobfiles from job where jobid = 1179; +----------+ | jobfiles | +----------+ | 1 | +----------+ Enter SQL query: select count(*) from file where jobid =1179; +-------+ | count | +-------+ | 1 | +-------+ $ mark * 2 files marked. $ lsmark *E:/ *WindowsImageBackup.delta $ ---------------------------------------------------------------------- (0006705) kern (administrator) - 2013-05-10 13:51 http://bugs.bacula.org/view.php?id=1979#c6705 ---------------------------------------------------------------------- For Martin: what is the job_metadata.xml object? I never heard of that. The only xml that I am aware of is what the Bacula Enterprise plugin produces when it is doing application VSS backups, which are entirely different from what is happening in the FileSet shown above. For Steve: Your SQL queries don't mean a lot to me. What is more important is what the output of the job log is. I don't really understand what you are doing, that is when you are running with EnableVSS=yes/no and whether those are backup jobs or verify jobs. Also, it would help if you would show the output of what you say "it is failing". As I say at the current time, it is not clear exactly what you are doing, and exactly what is failing or why. Possibly what is happening is that the entry for the directory E: is being ignored by the verify job, but then you haven't shown anything concerning it -- neither the FileSet your are using nor the Job resource, nor the output. ---------------------------------------------------------------------- (0006706) martin (reporter) - 2013-05-10 15:27 http://bugs.bacula.org/view.php?id=1979#c6706 ---------------------------------------------------------------------- It is all in the source code. $ grep -Ir 'job_metadata\.xml' src src/filed/backup.c: ff_pkt->object_name = (char *)"job_metadata.xml"; src/filed/job.c: if (strcmp(rop.object_name, "job_metadata.xml") == 0) { $ Strangely though, it doesn't seem to be used in the restore code. ---------------------------------------------------------------------- (0006707) kern (administrator) - 2013-05-10 16:45 http://bugs.bacula.org/view.php?id=1979#c6707 ---------------------------------------------------------------------- Yes, you are right. The code that writes out the job_metadata.xml really should do it only when the vss plugin is loaded and tells Bacula to save it. This is an oversight on my part. The RestoreObjects are only used by the vss plugin during application specific restores and not by Bacula core code. So saving this metadata is a "minor" inefficiency that I will fix. The RestoreObjects don't enter into any counting during restore or verifies so the user's problem lies elsewhere. ---------------------------------------------------------------------- (0006709) martin (reporter) - 2013-05-10 18:08 http://bugs.bacula.org/view.php?id=1979#c6709 ---------------------------------------------------------------------- You are right that RestoreObjects don't enter into any counting during restore or verifies, but I suspect that they *do* enter into the counting during backup (assuming encode_and_send_attributes is called and hence JobFiles is incremented). That causes the mismatch of job.jobfiles (2) v.s. the number of rows in the file table (1). ---------------------------------------------------------------------- (0006710) kern (administrator) - 2013-05-11 08:29 http://bugs.bacula.org/view.php?id=1979#c6710 ---------------------------------------------------------------------- RestoreObject shouldn't be sent off to the SD. I would be surprised if they are (though I have been surprised before). They should and will someday be sent off to the SD, but obviously like any other Bacula metadata they should not be counted as a file. RestoreObjects are just a form of metadata that (for backup or tape unfriendly designs such as Microsoft VSS) can be written at the end of a job but restored at the beginning of a restore job. ---------------------------------------------------------------------- (0006713) Steve Lee (reporter) - 2013-05-15 12:52 http://bugs.bacula.org/view.php?id=1979#c6713 ---------------------------------------------------------------------- Here are the job and fileset definitions and logs. I created 2 filesets (with and without vss) and 4 jobs (2 backup and 2 verify for each) Job { Name = "ZMAIL-Test" Client = "zmail" FileSet = "zmail-test" JobDefs = "Default" Level = Full Pool = PoolA Schedule = "Weekend" } Job { Name = "ZMAIL-Test-Verify" Verify Job = "ZMAIL-Test" Client = "zmail" FileSet = "zmail-test" JobDefs = "DefaultVerify" Schedule = "Weekend" } Job { Name = "ZMAIL-Test-novss" Client = "zmail" FileSet = "zmail-test-novss" JobDefs = "Default" Level = Full Pool = PoolA Schedule = "Weekend" } Job { Name = "ZMAIL-Test-Verify-novss" Verify Job = "ZMAIL-Test-novss" Client = "zmail" FileSet = "zmail-test-novss" JobDefs = "DefaultVerify" Schedule = "Weekend" } FileSet { Name = "zmail-test" Include { Options { signature = MD5 compression = GZIP aclsupport = yes } File = "E:/Test.txt" } } FileSet { Name = "zmail-test-novss" Enable VSS = no Include { Options { signature = MD5 compression = GZIP aclsupport = yes } File = "E:/Test.txt" } } 15-May 12:32 zbkmgr-dir JobId 1319: Begin pruning Jobs older than 6 months . 15-May 12:32 zbkmgr-dir JobId 1319: No Jobs found to prune. 15-May 12:32 zbkmgr-dir JobId 1319: Begin pruning Files. 15-May 12:32 zbkmgr-dir JobId 1319: No Files found to prune. 15-May 12:32 zbkmgr-dir JobId 1319: End auto prune. 15-May 12:37 zbkmgr-dir JobId 1320: Start Backup JobId 1320, Job=ZMAIL-Test.2013-05-15_12.37.44_03 15-May 12:37 zbkmgr-dir JobId 1320: Created new Volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" in catalog. 15-May 12:37 zbkmgr-dir JobId 1320: Using Device "FileStorage" 15-May 12:37 zbkstore-sd JobId 1320: Labeled new Volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" on device "FileStorage" (/zynstra/data/latestbackup). 15-May 12:37 zbkstore-sd JobId 1320: Wrote label to prelabeled Volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" on device "FileStorage" (/zynstra/data/latestbackup) 15-May 12:37 zbkmgr-dir JobId 1320: Max Volume jobs=1 exceeded. Marking Volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" as Used. 15-May 12:37 zwin-fd JobId 1320: Generate VSS snapshots. Driver="Win64 VSS", Drive(s)="E" 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "Task Scheduler Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "VSS Metadata Store Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "Performance Counters Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "System Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "ASR Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "Microsoft Exchange Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "IIS Config Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "Registry Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "COM+ REGDB Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "Shadow Copy Optimization Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "WMI Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zwin-fd JobId 1320: VSS Writer (BackupComplete): "IIS Metabase Writer", State: 0x1 (VSS_WS_STABLE) 15-May 12:37 zbkstore-sd JobId 1320: Job write elapsed time = 00:00:13, Transfer rate = 135 Bytes/second 15-May 12:37 zbkmgr-dir JobId 1320: Bacula zbkmgr-dir 5.2.6 (21Feb12): Build OS: x86_64-unknown-linux-gnu ubuntu 12.04 JobId: 1320 Job: ZMAIL-Test.2013-05-15_12.37.44_03 Backup Level: Full Client: "zmail" 5.2.10 (28Jun12) Microsoft Windows Server 2008 R2 Standard Edition Service Pack 1 (build 7601), 64-bit,Cross-compile,Win64 FileSet: "zmail-test" 2013-05-15 12:31:26 Pool: "PoolA" (From Job resource) Catalog: "MyCatalog" (From Client resource) Storage: "Default" (From Job resource) Scheduled time: 15-May-2013 12:37:42 Start time: 15-May-2013 12:37:46 End time: 15-May-2013 12:37:59 Elapsed time: 13 secs Priority: 10 FD Files Written: 2 SD Files Written: 2 FD Bytes Written: 816 (816 B) SD Bytes Written: 1,755 (1.755 KB) Rate: 0.1 KB/s Software Compression: None VSS: yes Encryption: yes Accurate: no Volume name(s): ZMAIL-Test.2013-05-15_12.37.44_03_1_Full Volume Session Id: 119 Volume Session Time: 1367913478 Last Volume Bytes: 2,454 (2.454 KB) Non-fatal FD errors: 0 SD Errors: 0 FD termination status: OK SD termination status: OK Termination: Backup OK 15-May 12:37 zbkmgr-dir JobId 1320: Begin pruning Jobs older than 6 months . 15-May 12:37 zbkmgr-dir JobId 1320: No Jobs found to prune. 15-May 12:37 zbkmgr-dir JobId 1320: Begin pruning Files. 15-May 12:37 zbkmgr-dir JobId 1320: No Files found to prune. 15-May 12:37 zbkmgr-dir JobId 1320: End auto prune. 15-May 12:38 zbkmgr-dir JobId 1321: Verifying against JobId=1320 Job=ZMAIL-Test.2013-05-15_12.37.44_03 15-May 12:38 zbkmgr-dir JobId 1321: Bootstrap records written to /var/bacula/working/zbkmgr-dir.restore.1.bsr 15-May 12:38 zbkmgr-dir JobId 1321: Start Verify JobId=1321 Level=VolumeToCatalog Job=ZMAIL-Test-Verify.2013-05-15_12.37.51_04 15-May 12:38 zbkmgr-dir JobId 1321: Using Device "FileStorage" 15-May 12:38 zbkstore-sd JobId 1321: Ready to read from volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" on device "FileStorage" (/zynstra/data/latestbackup). 15-May 12:38 zbkstore-sd JobId 1321: Forward spacing Volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" to file:block 0:229. 15-May 12:38 zbkstore-sd JobId 1321: End of Volume at file 0 on device "FileStorage" (/zynstra/data/latestbackup), Volume "ZMAIL-Test.2013-05-15_12.37.44_03_1_Full" 15-May 12:38 zbkstore-sd JobId 1321: End of all volumes. 15-May 12:38 zbkmgr-dir JobId 1321: Error: Bacula zbkmgr-dir 5.2.6 (21Feb12): Build OS: x86_64-unknown-linux-gnu ubuntu 12.04 JobId: 1321 Job: ZMAIL-Test-Verify.2013-05-15_12.37.51_04 FileSet: zmail-test Verify Level: VolumeToCatalog Client: zmail Verify JobId: 1320 Verify Job: ZMAIL-Test Start time: 15-May-2013 12:38:01 End time: 15-May-2013 12:38:02 Files Expected: 2 Files Examined: 1 Non-fatal FD errors: 0 FD termination status: OK SD termination status: OK Termination: *** Verify Error *** 15-May 12:38 zbkmgr-dir JobId 1321: Begin pruning Jobs older than 6 months . 15-May 12:38 zbkmgr-dir JobId 1321: No Jobs found to prune. 15-May 12:38 zbkmgr-dir JobId 1321: Begin pruning Files. 15-May 12:38 zbkmgr-dir JobId 1321: No Files found to prune. 15-May 12:38 zbkmgr-dir JobId 1321: End auto prune. 15-May 12:38 zbkmgr-dir JobId 1322: Start Backup JobId 1322, Job=ZMAIL-Test-novss.2013-05-15_12.38.11_06 15-May 12:38 zbkmgr-dir JobId 1322: Created new Volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" in catalog. 15-May 12:38 zbkmgr-dir JobId 1322: Using Device "FileStorage" 15-May 12:38 zbkstore-sd JobId 1322: Labeled new Volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" on device "FileStorage" (/zynstra/data/latestbackup). 15-May 12:38 zbkstore-sd JobId 1322: Wrote label to prelabeled Volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" on device "FileStorage" (/zynstra/data/latestbackup) 15-May 12:38 zbkmgr-dir JobId 1322: Max Volume jobs=1 exceeded. Marking Volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" as Used. 15-May 12:38 zbkstore-sd JobId 1322: Job write elapsed time = 00:00:05, Transfer rate = 251 Bytes/second 15-May 12:38 zbkmgr-dir JobId 1322: Bacula zbkmgr-dir 5.2.6 (21Feb12): Build OS: x86_64-unknown-linux-gnu ubuntu 12.04 JobId: 1322 Job: ZMAIL-Test-novss.2013-05-15_12.38.11_06 Backup Level: Full Client: "zmail" 5.2.10 (28Jun12) Microsoft Windows Server 2008 R2 Standard Edition Service Pack 1 (build 7601), 64-bit,Cross-compile,Win64 FileSet: "zmail-test-novss" 2013-05-15 12:38:11 Pool: "PoolA" (From Job resource) Catalog: "MyCatalog" (From Client resource) Storage: "Default" (From Job resource) Scheduled time: 15-May-2013 12:38:10 Start time: 15-May-2013 12:38:14 End time: 15-May-2013 12:38:19 Elapsed time: 5 secs Priority: 10 FD Files Written: 1 SD Files Written: 1 FD Bytes Written: 816 (816 B) SD Bytes Written: 1,257 (1.257 KB) Rate: 0.2 KB/s Software Compression: None VSS: no Encryption: yes Accurate: no Volume name(s): ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full Volume Session Id: 121 Volume Session Time: 1367913478 Last Volume Bytes: 1,986 (1.986 KB) Non-fatal FD errors: 0 SD Errors: 0 FD termination status: OK SD termination status: OK Termination: Backup OK 15-May 12:38 zbkmgr-dir JobId 1322: Begin pruning Jobs older than 6 months . 15-May 12:38 zbkmgr-dir JobId 1322: No Jobs found to prune. 15-May 12:38 zbkmgr-dir JobId 1322: Begin pruning Files. 15-May 12:38 zbkmgr-dir JobId 1322: No Files found to prune. 15-May 12:38 zbkmgr-dir JobId 1322: End auto prune. 15-May 12:38 zbkmgr-dir JobId 1323: Verifying against JobId=1322 Job=ZMAIL-Test-novss.2013-05-15_12.38.11_06 15-May 12:38 zbkmgr-dir JobId 1323: Bootstrap records written to /var/bacula/working/zbkmgr-dir.restore.2.bsr 15-May 12:38 zbkmgr-dir JobId 1323: Start Verify JobId=1323 Level=VolumeToCatalog Job=ZMAIL-Test-Verify-novss.2013-05-15_12.38.19_07 15-May 12:38 zbkmgr-dir JobId 1323: Using Device "FileStorage" 15-May 12:38 zbkstore-sd JobId 1323: Ready to read from volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" on device "FileStorage" (/zynstra/data/latestbackup). 15-May 12:38 zbkstore-sd JobId 1323: Forward spacing Volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" to file:block 0:235. 15-May 12:38 zbkstore-sd JobId 1323: End of Volume at file 0 on device "FileStorage" (/zynstra/data/latestbackup), Volume "ZMAIL-Test-novss.2013-05-15_12.38.11_06_2_Full" 15-May 12:38 zbkstore-sd JobId 1323: End of all volumes. 15-May 12:38 zbkmgr-dir JobId 1323: Bacula zbkmgr-dir 5.2.6 (21Feb12): Build OS: x86_64-unknown-linux-gnu ubuntu 12.04 JobId: 1323 Job: ZMAIL-Test-Verify-novss.2013-05-15_12.38.19_07 FileSet: zmail-test-novss Verify Level: VolumeToCatalog Client: zmail Verify JobId: 1322 Verify Job: ZMAIL-Test-novss Start time: 15-May-2013 12:38:21 End time: 15-May-2013 12:38:22 Files Expected: 1 Files Examined: 1 Non-fatal FD errors: 0 FD termination status: OK SD termination status: OK Termination: Verify OK 15-May 12:38 zbkmgr-dir JobId 1323: Begin pruning Jobs older than 6 months . 15-May 12:38 zbkmgr-dir JobId 1323: No Jobs found to prune. 15-May 12:38 zbkmgr-dir JobId 1323: Begin pruning Files. 15-May 12:38 zbkmgr-dir JobId 1323: No Files found to prune. 15-May 12:38 zbkmgr-dir JobId 1323: End auto prune. ---------------------------------------------------------------------- (0006761) windwalker78 (reporter) - 2014-02-14 12:11 http://bugs.bacula.org/view.php?id=1979#c6761 ---------------------------------------------------------------------- We are all suffering from this issue (5.2.12). Is there a way to workaround this with a custom patch/mod? We tried to contact the official commercial bacula representatives, but no feedback sofar... Issue History Date Modified Username Field Change ====================================================================== 2013-01-15 16:24 angeloio New Issue 2013-02-15 21:29 kern Note Added: 0006610 2013-02-15 21:29 kern Status new => feedback 2013-05-01 22:30 Steve Lee Note Added: 0006688 2013-05-01 22:34 Steve Lee Note Added: 0006689 2013-05-02 11:50 martin Note Added: 0006690 2013-05-05 08:06 Steve Lee Note Added: 0006691 2013-05-07 15:37 ebollengier Severity major => minor 2013-05-10 13:51 kern Note Added: 0006705 2013-05-10 15:27 martin Note Added: 0006706 2013-05-10 16:45 kern Note Added: 0006707 2013-05-10 18:08 martin Note Added: 0006709 2013-05-11 08:29 kern Note Added: 0006710 2013-05-15 12:52 Steve Lee Note Added: 0006713 2014-02-14 12:11 windwalker78 Note Added: 0006761 ====================================================================== |