we are using Bacula on a Linux 2.6.18-238.5.1.el5PAE system, and have a Dell
TL-2000 two drives (dev/nst0 and dev/nst1) autochanger. Bacula runs fine but we
always encounter a tape error writing final EOF when using drive 1. There is an
error message regarding the tape EOF, the tape does not fill up, bacula mounts
the next tape, and continues the backup. The job finishes correctly. What is
noticeable is that a part of the error message is identical (dev.c:1745 ioctl)
and the error seems to appears at the same block (c:577) for 2 different tapes
as shown below. The amount of data written to each tape varies before the error
happening. I do not know if it makes a difference but just wanted to mention
it. What could be the cause of this problem ?
below are the logs:
EOF error on tape 0015MEL5:
08-May 03:00 saver.engr-dir JobId 213: Start Backup JobId 213,
Job=saver-me.2011-05-08_03.00.01_15
08-May 03:00 saver.engr-dir JobId 213: Using Device Drive-1
08-May 02:58 saver-me-fd JobId 213: DIR and FD clocks differ by -65 seconds, FD
automatically compensating.
08-May 02:58 saver-me-sd JobId 213: Spooling data ...
08-May 02:58 saver-me-sd JobId 213: Job write elapsed time = 00:00:01, Transfer
rate = 157.0 K Bytes/second
08-May 02:58 saver-me-sd JobId 213: Committing spooled data to Volume
0015MEL5. Despooling 157,763 bytes ...
08-May 02:58 saver-me-sd JobId 213: Error: block.c:577 Write error at 10:1 on
device Drive-1 (/dev/nst1). ERR=Input/output error.
08-May 02:58 saver-me-sd JobId 213: Error: Error writing final EOF to tape.
This Volume may not be readable.
dev.c:1745 ioctl MTWEOF error on Drive-1 (/dev/nst1). ERR=Input/output error.
08-May 02:58 saver-me-sd JobId 213: End of medium on Volume 0015MEL5
Bytes=5,504,034,816 Blocks=85,317 at 08-May-2011 02:58.
08-May 02:58 saver-me-sd JobId 213: 3307 Issuing autochanger unload slot 15,
drive 1 command.
08-May 03:04 saver-me-sd JobId 213: 3301 Issuing autochanger loaded? drive 1
command.
08-May 03:04 saver-me-sd JobId 213: 3302 Autochanger loaded? drive 1, result:
nothing loaded.
08-May 03:04 saver-me-sd JobId 213: 3304 Issuing autochanger load slot 16,
drive 1 command.
08-May 03:05 saver-me-sd JobId 213: 3305 Autochanger load slot 16, drive 1,
status is OK.
08-May 03:05 saver-me-sd JobId 213: Wrote label to prelabeled Volume 0016MEL5
on device Drive-1 (/dev/nst1)
08-May 03:05 saver-me-sd JobId 213: New volume 0016MEL5 mounted on device
Drive-1 (/dev/nst1) at 08-May-2011 03:05.
08-May 03:05 saver-me-sd JobId 213: Despooling elapsed time = 00:00:01,
Transfer rate = 157.7 K Bytes/second
08-May 03:05 saver-me-sd JobId 213: Sending spooled attrs to the Director.
Despooling 462 bytes ...
08-May 03:06 saver.engr-dir JobId 213: Bacula saver.engr-dir 5.0.3 (30Aug10):
08-May-2011 03:06:20
EOF error on tape 0016MEL5:
09-May 03:00 saver.engr-dir JobId 225: Start Backup JobId 225,
Job=guss.2011-05-09_03.00.01_10
09-May 03:00 saver.engr-dir JobId 225: Using Device Drive-1
09-May 02:58 saver-me-sd JobId 225: Spooling data ...
09-May 03:00 guss-fd JobId 225: Generate VSS snapshots. Driver=VSS WinXP,
Drive(s)=C
09-May 03:00 guss-fd JobId 225: VSS Writer (BackupComplete): MSDEWriter,
State: 0x1 (VSS_WS_STABLE)
09-May 02:59 saver-me-sd JobId 225: Job write elapsed time = 00:00:17, Transfer
rate = 6.654 M Bytes/second
09-May 03:00 guss-fd JobId 225: VSS Writer (BackupComplete): Microsoft Writer
(Bootable State), State: 0x1 (VSS_WS_STABLE)
09-May 02:59 saver-me-sd JobId 225: Committing spooled data to Volume
0016MEL5. Despooling 113,227,156 bytes ...
09-May 03:00 guss-fd JobId 225: VSS Writer (BackupComplete): Microsoft Writer
(Service State), State: 0x1 (VSS_WS_STABLE)
09-May 03:00 guss-fd JobId 225: VSS Writer (BackupComplete): WMI Writer,
State: 0x1 (VSS_WS_STABLE)
09-May 02:59 saver-me-sd JobId 225: Error: block.c:577 Write error at 4:3 on
device Drive-1 (/dev/nst1). ERR=Input/output error.
09-May 02:59 saver-me-sd JobId 225: Error: Error writing final EOF to tape.
This Volume may not be readable.
dev.c:1745 ioctl MTWEOF error on Drive-1 (/dev/nst1). ERR=Input/output error.
09-May 02:59 saver-me-sd JobId 225: End of medium on Volume 0016MEL5
Bytes=2,538,805,248 Blocks=39,353 at 09-May-2011 02:59.
09-May 02:59 saver-me-sd JobId 225: 3307 Issuing autochanger unload slot 16,
drive 1 command.
09-May 03:04 saver-me-sd JobId 225: 3301 Issuing autochanger loaded? drive 1
command.
09-May 03:04 saver-me-sd JobId 225: 3302 Autochanger loaded? drive 1, result:
nothing loaded.
09-May 03:04 saver-me-sd JobId 225: 3304 Issuing autochanger load slot 17,
drive 1 command.
09-May 03:05 saver-me-sd JobId 225: 3305 Autochanger load slot 17, drive 1,
status is OK.
09-May 03:05 saver-me-sd JobId 225: Wrote label to prelabeled Volume 0017MEL5
on device Drive-1 (/dev/nst1)
09-May 03:05 saver-me-sd JobId 225: New volume 0017MEL5 mounted on device
Drive-1 (/dev/nst1) at 09-May-2011 03:05.
09-May 03:05 saver-me-sd JobId 225: Despooling elapsed time = 00:00:01,
