I never got a reply on this, but as the disquieting "previously written"
and "number of files mismatch" messages did not reoccur on the following
tape change I will not pursue this further. The incorrect volume name
in the "Committing spooled data" message I can live with.
HTH
TS
Am 01.02.2013 12:33, schrieb Tilman Schmidt:
> On 31.01.2013 11:01, /me wrote:
>> - The seventh job [...] reported the tape change: [...]
>> - The next four jobs (always in order of completion) did however
>> still report writing to tape Daily_2, the last one apparently
>> even starting to use it well after it had been unloaded:
>
> Looking at the director's completion reports I see that, although
> the SD logged "Committing to "Daily_2" for these jobs, the data
> went actually to "Daily_1":
>
> 30-Jan 20:15 bacula-sd JobId 6156: Committing spooled data to Volume
> "Daily_2". Despooling 1,602,040,011 bytes ...
> 30-Jan 20:22 bacula-sd JobId 6156: Despooling elapsed time = 00:00:30,
> Transfer rate = 53.40 M Bytes/second
> 30-Jan 20:22 bacula-sd JobId 6156: Elapsed time=00:12:46, Transfer
> rate=2.089 M Bytes/second
> 30-Jan 20:22 bacula-sd JobId 6156: Sending spooled attrs to the
> Director. Despooling 29,281 bytes ...
> 30-Jan 20:23 backup-dir JobId 6156: Bacula backup-dir 5.2.12 (12Sep12):
> Build OS: x86_64-redhat-linux-gnu redhat Enterprise release
> JobId: 6156
> Job: w2k3-web-dmz.2013-01-30_20.05.01_37
> Backup Level: Incremental, since=2013-01-29 20:11:20
> Client: "w2k3-web-dmz-fd" 5.2.10 (28Jun12) Microsoft
> Windows Home ServerStandard Edition Service Pack 2 (build
> 3790),Cross-compile,Win32
> FileSet: "w2k3-web-dmz" 2012-01-20 22:05:00
> Pool: "Daily" (From Run pool override)
> Catalog: "MyCatalog" (From Client resource)
> Storage: "LTO-3" (From Job resource)
> Scheduled time: 30-Jan-2013 20:05:01
> Start time: 30-Jan-2013 20:10:13
> End time: 30-Jan-2013 20:23:03
> Elapsed time: 12 mins 50 secs
> Priority: 10
> FD Files Written: 90
> SD Files Written: 90
> FD Bytes Written: 1,600,536,726 (1.600 GB)
> SD Bytes Written: 1,600,551,989 (1.600 GB)
> Rate: 2078.6 KB/s
> Software Compression: None
> VSS: yes
> Encryption: no
> Accurate: no
> Volume name(s): Daily_1
> Volume Session Id: 290
> Volume Session Time: 1357817315
> Last Volume Bytes: 5,355,915,264 (5.355 GB)
> Non-fatal FD errors: 0
> SD Errors: 0
> FD termination status: OK
> SD termination status: OK
> Termination: Backup OK
>
> So apparently that's just a logging imperfection and I'll stop
> worrying about that.
>
>> - Then, most disquieting, the next one reported that tape as
>> previously written, and a file count mismatch:
>>
>> 30-Jan 20:28 bacula-sd JobId 6152: Volume "Daily_1" previously written,
>> moving to end of data.
>> 30-Jan 20:30 bacula-sd JobId 6152: Warning: For Volume "Daily_1":
>> The number of files mismatch! Volume=4 Catalog=3
>> Correcting Catalog
>
> Again reviewing the director reports it would seem that no data
> was lost. The "SD Bytes Written" and "Last Volume Bytes" values
> do sum up approximately, even across the ominous message:
>
> [ts@backup ~]$ grep -e "Last Volume Bytes" -e "SD Bytes Written" -e "End
> of medium" -e "previously written" /tmp/log-20130130
> SD Bytes Written: 428,089,875 (428.0 MB)
> Last Volume Bytes: 796,026,470,400 (796.0 GB)
> SD Bytes Written: 1,214,712,798 (1.214 GB)
> Last Volume Bytes: 797,242,134,528 (797.2 GB)
> SD Bytes Written: 45,777,531 (45.77 MB)
> Last Volume Bytes: 797,288,002,560 (797.2 GB)
> SD Bytes Written: 27,729,514 (27.72 MB)
> Last Volume Bytes: 797,315,807,232 (797.3 GB)
> SD Bytes Written: 123,939,387 (123.9 MB)
> Last Volume Bytes: 797,439,863,808 (797.4 GB)
> SD Bytes Written: 1,264,330,981 (1.264 GB)
> Last Volume Bytes: 798,705,202,176 (798.7 GB)
> 30-Jan 20:18 bacula-sd JobId 6142: End of medium on Volume "Daily_2"
> Bytes=799,806,099,456 Blocks=12,397,787 at 30-Jan-2013 20:18.
> SD Bytes Written: 4,849,031,881 (4.849 GB)
> Last Volume Bytes: 3,754,146,816 (3.754 GB)
> SD Bytes Written: 1,600,551,989 (1.600 GB)
> Last Volume Bytes: 5,355,915,264 (5.355 GB)
> SD Bytes Written: 2,555,884,712 (2.555 GB)
> Last Volume Bytes: 7,913,751,552 (7.913 GB)
> SD Bytes Written: 1,440,289,909 (1.440 GB)
> Last Volume Bytes: 9,355,143,168 (9.355 GB)
> SD Bytes Written: 5,604,420,853 (5.604 GB)
> Last Volume Bytes: 14,963,816,448 (14.96 GB)
> SD Bytes Written: 4,375,024,239 (4.375 GB)
> Last Volume Bytes: 19,342,761,984 (19.34 GB)
> 30-Jan 20:28 bacula-sd JobId 6152: Volume "Daily_1" previously written,
> moving to end of data.
> SD Bytes Written: 5,464,351,240 (5.464 GB)
> Last Volume Bytes: 24,811,186,176 (24.81 GB)
> SD Bytes Written: 18,312,939,961 (18.31 GB)
> Last Volume Bytes: 43,137,755,136 (43.13 GB)
> SD Bytes Written: 9,272,525,456 (9.272 GB)
> Last Volume Bytes: 52,417,161,216 (52.41 GB)
> SD Bytes Written: 434,418,948 (434.4 MB)
> Last Volume Bytes: 52,851,972,096 (52.85 GB)
> SD Bytes Written: 1,076,781,093 (1.076 GB)
> Last Volume Bytes: 53,929,838,592 (53.92 GB)
> SD Bytes Written: 4,742,245,237 (4.742 GB)
> Last Volume Bytes: 58,675,663,872 (58.67 GB)
> [ts@backup ~]$
>
> Still I would sleep more peacefully if there was an explanation for
> the unexpected "previously written" and "number of files mismatch"
> messages.
>
> Thanks,
> Tilman
>
--
Tilman Schmidt
Phoenix Software GmbH
Bonn, Germany
signature.asc
Description: OpenPGP digital signature
------------------------------------------------------------------------------
Everyone hates slow websites. So do we.
Make your web apps faster with AppDynamics
Download AppDynamics Lite for free today:
http://p.sf.net/sfu/appdyn_d2d_feb _______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
|
