Re: [Bacula-users] doubt on tape change with concurrent jobs

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_jan

_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users