Hello everybody,
I am experiencing a frequent error (almost stable, but sometimes it
worked). Bacula is MySQL version 1.38.11-3 on a RedHat ES 4.04 running on
an HP Proliant Server. The tape is an HP MSL6000 LTO-3 device with
autochanger and 2 drives.
When an EOT is reached the tape is unloaded and a new tape loaded, the
label is recognized correctly, but the first write receive the same error
response of the exhausted tape, and also the number of blocks is the one
of the old tape. So the job is aborted. The next job uses the newly
mounted tape correctly, up to the new tape change and the problem presents
again.
Here are the two relevant portion of logs:
24-nov 22:16 bacula-dir: Start Backup JobId 10779,
Job=webfs1-job.2006-11-24_20.35.00
24-nov 22:16 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
24-nov 22:16 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
3.
24-nov 22:16 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
24-nov 22:16 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
3.
24-nov 22:17 bacula-sd: Volume "web-001" previously written, moving to end
of data.
24-nov 22:17 bacula-sd: Ready to append to end of Volume "web-001" at
file=5.
25-nov 13:35 bacula-sd: End of Volume "web-001" at 505:6453 on device
"LTO1" (/dev/lto1). Write of 64512 bytes got -1.
25-nov 13:35 bacula-sd: Re-read of last block succeeded.
25-nov 13:35 bacula-sd: End of medium on Volume "web-001"
Bytes=505,020,009,198 Blocks=7,828,312 at 25-nov-2006 13:35.
25-nov 13:36 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
25-nov 13:36 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
3.
25-nov 13:36 bacula-sd: 3307 Issuing autochanger "unload slot 3, drive 0"
command.
25-nov 13:36 bacula-sd: 3304 Issuing autochanger "load slot 4, drive 0"
command.
25-nov 13:37 bacula-sd: 3305 Autochanger "load slot 4, drive 0", status is
OK.
25-nov 13:37 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
25-nov 13:37 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
4.
25-nov 13:37 bacula-sd: Wrote label to prelabeled Volume "web-002" on
device "LTO1" (/dev/lto1)
25-nov 13:37 bacula-sd: New volume "web-002" mounted on device "LTO1"
(/dev/lto1) at 25-nov-2006 13:37.
25-nov 13:37 bacula-sd: End of Volume "web-002" at 0:1 on device "LTO1"
(/dev/lto1). Write of 64512 bytes got -1.
25-nov 13:37 bacula-sd: webfs1-job.2006-11-24_20.35.00 Error: Re-read of
last block OK, but block numbers differ. Last block=0 Current
block=7756453.
25-nov 13:37 bacula-sd: webfs1-job.2006-11-24_20.35.00 Fatal error:
append.c:207 Fatal append error on device "LTO1" (/dev/lto1): ERR=
25-nov 13:37 webfs3: webfs1-job.2006-11-24_20.35.00 Fatal error:
backup.c:499 Network send error to SD.
25-nov 13:38 bacula-dir: Start Backup JobId 10780,
Job=webfs3-job.2006-11-24_20.35.01
25-nov 13:38 bacula-dir: There are no Jobs associated with Volume
"web-002". Marking it purged.
25-nov 13:38 bacula-dir: Recycled volume "web-002"
25-nov 13:38 webfs3: ClientRunBeforeJob: Shutting down SMB services: [ OK
]
25-nov 13:38 webfs3: ClientRunBeforeJob: smbd: no process killed
25-nov 13:38 webfs3: ClientRunBeforeJob: Starting SMB services: [ OK ]
25-nov 13:38 webfs3: ClientRunBeforeJob: [ OK ]
25-nov 13:38 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
25-nov 13:38 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
4.
25-nov 13:38 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
25-nov 13:38 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
4.
25-nov 13:38 bacula-sd: Recycled volume "web-002" on device "LTO1"
(/dev/lto1), all previous data lost.
26-nov 06:18 bacula-sd: End of Volume "web-002" at 572:11760 on device
"LTO1" (/dev/lto1). Write of 64512 bytes got -1.
26-nov 06:18 bacula-sd: Re-read of last block succeeded.
26-nov 06:18 bacula-sd: End of medium on Volume "web-002"
Bytes=572,722,041,019 Blocks=8,877,760 at 26-nov-2006 06:18.
26-nov 06:18 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
26-nov 06:18 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
4.
26-nov 06:18 bacula-sd: 3307 Issuing autochanger "unload slot 4, drive 0"
command.
26-nov 06:19 bacula-sd: 3304 Issuing autochanger "load slot 5, drive 0"
command.
26-nov 06:19 bacula-sd: 3305 Autochanger "load slot 5, drive 0", status is
OK.
26-nov 06:19 bacula-sd: 3301 Issuing autochanger "loaded drive 0" command.
26-nov 06:19 bacula-sd: 3302 Autochanger "loaded drive 0", result is Slot
5.
26-nov 06:20 bacula-sd: Wrote label to prelabeled Volume "web-003" on
device "LTO1" (/dev/lto1)
26-nov 06:20 bacula-sd: New volume "web-003" mounted on device "LTO1"
(/dev/lto1) at 26-nov-2006 06:20.
26-nov 06:20 bacula-sd: End of Volume "web-003" at 0:1 on device "LTO1"
(/dev/lto1). Write of 64512 bytes got -1.
26-nov 06:20 bacula-sd: webfs3-job.2006-11-24_20.35.01 Error: Re-read of
last block OK, but block numbers differ. Last bloc