Hi list, I am running Bacula 1.36.3 on Gentoo Linux, and it has been working well for some time. I received a verify error recently though, and it appears to be a discrepancy in the number of files expected versus number of files found on the tape.
>From the backup log: FD Files Written: 6,049 SD Files Written: 6,049 >From the verify log: Files Expected: 6,050 Files Examined: 6,049 The previous week's run of this job was reported as successful. It spanned two tapes as well. There were slightly fewer files on that one though -- 5,967. I am running a HP DAT 40x6 autochanger with simulated barcoding. Spooling is enabled. This particular backup typically spans two tapes, and this time was no exception. Full logs are below -- first the successful backup one, then the failed verify one: ---------- Subject: Bacula: Backup OK of nefertiti-fd Full 03-Aug 01:00 iris-dir: Start Backup JobId 3136, Job=Nefertiti_SQL_Backup.2005-08-03_01.00.00 03-Aug 01:00 iris-sd: 3301 Issuing autochanger "loaded drive 0" command. 03-Aug 01:00 iris-sd: 3302 Autochanger "loaded drive 0", result: nothing loaded. 03-Aug 01:00 iris-sd: 3304 Issuing autochanger "load slot 5, drive 0" command. 03-Aug 01:00 iris-sd: 3305 Autochanger "load slot 5, drive 0", status is OK. 03-Aug 01:01 iris-sd: Volume "CoLo1E" previously written, moving to end of data. 03-Aug 01:01 iris-sd: Ready to append to end of Volume "CoLo1E" at file=1. 03-Aug 01:01 iris-sd: Spooling data ... 03-Aug 01:28 iris-sd: Writing spooled data to Volume. Despooling 9,358,236,854 bytes ... 03-Aug 02:08 iris-sd: Writing spooled data to Volume. Despooling 9,358,172,491 bytes ... 03-Aug 02:48 iris-sd: Writing spooled data to Volume. Despooling 9,358,172,660 bytes ... 03-Aug 03:30 iris-sd: Writing spooled data to Volume. Despooling 9,358,237,436 bytes ... 03-Aug 04:14 iris-sd: Writing spooled data to Volume. Despooling 9,358,172,495 bytes ... 03-Aug 04:57 iris-sd: Writing spooled data to Volume. Despooling 9,358,172,714 bytes ... 03-Aug 05:39 iris-sd: Writing spooled data to Volume. Despooling 9,358,172,863 bytes ... 03-Aug 05:43 iris-sd: End of Volume "CoLo1E" at 59:8776 on device /dev/nst0. Write of 64512 bytes got -1. 03-Aug 05:43 iris-sd: Re-read of last block succeeded. 03-Aug 05:43 iris-sd: End of medium on Volume "CoLo1E" Bytes=58,601,019,479 Blocks=908,375 at 03-Aug-2005 05:43. 03-Aug 05:45 iris-dir: Pruned 1 Job on Volume "CoLo4A" from catalog. 03-Aug 05:45 iris-dir: Pruned 2 Jobs on Volume "CoLo4B" from catalog. 03-Aug 05:45 iris-dir: Pruned 4 Jobs on Volume "CoLo4C" from catalog. 03-Aug 05:45 iris-dir: Pruned 42 Jobs on Volume "CoLo4D" from catalog. 03-Aug 05:45 iris-dir: Pruned 6 Jobs on Volume "CoLo4E" from catalog. 03-Aug 05:46 iris-dir: Pruned 2 Jobs on Volume "CoLo1B" from catalog. 03-Aug 05:46 iris-dir: Recycled volume "CoLo1A" 03-Aug 05:46 iris-sd: 3301 Issuing autochanger "loaded drive 0" command. 03-Aug 05:46 iris-sd: 3302 Autochanger "loaded drive 0", result is Slot 5. 03-Aug 05:46 iris-sd: 3303 Issuing autochanger "unload slot 5, drive 0" command. 03-Aug 05:46 iris-sd: 3304 Issuing autochanger "load slot 1, drive 0" command. 03-Aug 05:47 iris-sd: 3305 Autochanger "load slot 1, drive 0", status is OK. 03-Aug 05:47 iris-sd: Recycled volume "CoLo1A" on device "/dev/nst0", all previous data lost. 03-Aug 05:47 iris-sd: New volume "CoLo1A" mounted on device /dev/nst0 at 03-Aug-2005 05:47. 03-Aug 06:33 iris-sd: Committing spooled data to Volume. Despooling 1,668,737,453 bytes ... 03-Aug 06:40 iris-sd: Sending spooled attrs to the Director. Despooling 2,160,047 bytes ... 03-Aug 06:40 iris-dir: Bacula 1.36.3 (22Apr05): 03-Aug-2005 06:40:47 JobId: 3136 Job: Nefertiti_SQL_Backup.2005-08-03_01.00.00 Backup Level: Full Client: nefertiti-fd FileSet: "Nefertiti SQLBackups" 2004-11-02 16:02:50 Pool: "Default" Storage: "Autochanger" Start time: 03-Aug-2005 01:00:01 End time: 03-Aug-2005 06:40:47 FD Files Written: 6,049 SD Files Written: 6,049 FD Bytes Written: 67,100,301,284 SD Bytes Written: 67,101,360,504 Rate: 3281.8 KB/s Software Compression: None Volume name(s): CoLo1A|CoLo1E Volume Session Id: 1 Volume Session Time: 1123041637 Last Volume Bytes: 8,601,144,015 Non-fatal FD errors: 0 SD Errors: 0 FD termination status: OK SD termination status: OK Termination: Backup OK 03-Aug 06:40 iris-dir: Begin pruning Jobs. 03-Aug 06:40 iris-dir: No Jobs found to prune. 03-Aug 06:40 iris-dir: Begin pruning Files. 03-Aug 06:40 iris-dir: Pruned 0 Files from 1 Jobs for client nefertiti-fd from catalog. 03-Aug 06:40 iris-dir: End auto prune. ---------- Subject: Bacula: Verify Error of nefertiti-fd Verify Volume to Catalog 03-Aug 12:36 iris-dir: Start Verify JobId=3143 Level=VolumeToCatalog Job=Nefertiti_SQL_Verify.2005-08-03_01.10.00 03-Aug 12:36 iris-dir: Verifying against JobId=3136 Job=Nefertiti_SQL_Backup.2005-08-03_01.00.00 03-Aug 12:36 iris-dir: Bootstrap records written to /var/bacula/restore.bsr 03-Aug 12:36 iris-dir: 03-Aug 12:36 iris-dir: The job will require the following Volumes: 03-Aug 12:36 iris-dir: 03-Aug 12:36 iris-dir: CoLo1A 03-Aug 12:36 iris-dir: CoLo1E 03-Aug 12:36 iris-dir: 03-Aug 12:37 iris-sd: 3301 Issuing autochanger "loaded drive 0" command. 03-Aug 12:37 iris-sd: 3302 Autochanger "loaded drive 0", result is Slot 2. 03-Aug 12:37 iris-sd: 3303 Issuing autochanger "unload slot 2, drive 0" command. 03-Aug 12:38 iris-sd: 3304 Issuing autochanger "load slot 1, drive 0" command. 03-Aug 12:39 iris-sd: 3305 Autochanger "load slot 1, drive 0", status is OK. 03-Aug 12:39 iris-sd: Ready to read from volume "CoLo1A" on device /dev/nst0. 03-Aug 12:39 iris-sd: Forward spacing to file:block 0:1. 03-Aug 13:27 iris-sd: End of Volume at file 8 on device /dev/nst0, Volume "CoLo1A" 03-Aug 13:28 iris-sd: Nefertiti_SQL_Verify.2005-08-03_01.10.00 Warning: Wrong Volume mounted on device /dev/nst0: Wanted CoLo1E have CoLo1A 03-Aug 13:28 iris-sd: 3301 Issuing autochanger "loaded drive 0" command. 03-Aug 13:28 iris-sd: 3302 Autochanger "loaded drive 0", result is Slot 1. 03-Aug 13:28 iris-sd: 3303 Issuing autochanger "unload slot 1, drive 0" command. 03-Aug 13:29 iris-sd: 3304 Issuing autochanger "load slot 5, drive 0" command. 03-Aug 13:29 iris-sd: 3305 Autochanger "load slot 5, drive 0", status is OK. 03-Aug 13:30 iris-sd: Ready to read from volume "CoLo1E" on device /dev/nst0. 03-Aug 13:30 iris-sd: Forward spacing to file:block 1:0. 03-Aug 15:34 iris-sd: End of Volume at file 60 on device /dev/nst0, Volume "CoLo1E" 03-Aug 15:34 iris-sd: End of all volumes. 03-Aug 15:34 iris-dir: Nefertiti_SQL_Verify.2005-08-03_01.10.00 Error: Bacula 1.36.3 (22Apr05): 03-Aug-2005 15:34:46 JobId: 3143 Job: Nefertiti_SQL_Verify.2005-08-03_01.10.00 FileSet: Nefertiti SQLBackups Verify Level: VolumeToCatalog Client: nefertiti-fd Verify JobId: 3136 Verify Job: Nefertiti SQL Backup Start time: 03-Aug-2005 12:36:09 End time: 03-Aug-2005 15:34:46 Files Expected: 6,050 Files Examined: 6,049 Non-fatal FD errors: 0 FD termination status: OK SD termination status: OK Termination: *** Verify Error *** ---------- Am I missing any red flags here, or should I submit a bug report? Thanks! Ryan Colp ------------------------------------------------------- SF.Net email is Sponsored by the Better Software Conference & EXPO September 19-22, 2005 * San Francisco, CA * Development Lifecycle Practices Agile & Plan-Driven Development * Managing Projects & Teams * Testing & QA Security * Process Improvement & Measurement * http://www.sqe.com/bsce5sf _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
