[Bacula-users] New volumes put into "Full" status in succession from sin

Hi folks,

I received a "Backup Fatal Error" report from one of my prod backups last evening. After going through the report, I noticed the initial volume that was being used went in Error. Bacula loaded a new volume from scratch pool, continued with the backups and after writing less than 18GB of data, marked the new volume with "Full" status. This went on with 2 more new volumes with very little data actually written to each volume. Any idea what happened? Following is the output from "bconsole" "list media" command:

Pool: Incrementals
+---------+------------+-----------+---------+----------------+---------------------------------------------------+
| MediaId | VolumeName | VolStatus | Enabled | VolBytes          | V LastWritten       |
+---------+------------+-----------+---------+-------------------+----------+-------------------------------------+
|      21 | 625AAL    | Full      |       1 | 1,909,612,486,656 | 2008-10-21 01:51:33 |
|      26 | 937ABO    | Full      |       1 | 1,740,294,807,552 | 2008-11-23 11:05:24 |
|      29 | 938ABO   | Full      |       1 | 1,816,487,156,736 | 2008-12-28 11:13:37 |
|      32 | 154ADU   | Error     |       1 |   973,151,327,232 | 2009-01-18 11:43:05 |
|      35 | 150ADU       | Full      |       1 |    17,639,129,088 | 2009-01-20 00:34:17 |
|      36 | 000019   | Full      |       1 |     2,147,088,384 | 2009-01-20 00:39:33 |
|      37 | 000020       | Full      |       1 |     4,294,112,256 | 2009-01-20 00:49:35 |
|      38 | 000021    | Append    |     1 |     7,904,526,336 | 2009-01-20 01:00:51 |
+---------+------------+-----------+---------+-------------------+----------+------------------------------------+

Note: I'm using LTO4 tape drives.

Following is the actual Report:

20-Jan 00:12 baculaserver-dir JobId 7413: Start Backup JobId 7413, Job=BACKUPSRV.2009-01-19_22.40.19
20-Jan 00:12 baculaserver-dir JobId 7413: Using Device "LTO4_1"
baculaserver-fd JobId 7413:      /home is a different filesystem. Will not descend from / into /home
baculaserver-fd JobId 7413:      /export/sbin is a different filesystem. Will not descend from / into /export/sbin
20-Jan 00:12 baculaserver-sd JobId 7413: Spooling data ...
baculaserver-fd JobId 7413:      /export/shared is a different filesystem. Will not descend from / into /export/shared
baculaserver-fd JobId 7413:      /export/logs is a different filesystem. Will not descend from / into /export/logs
baculaserver-fd JobId 7413:      /var/lib/nfs/rpc_pipefs is a different filesystem. Will not descend from / into /var/lib/nfs/rpc_pipefs
baculaserver-fd JobId 7413:      /var/lib/database is a different filesystem. Will not descend from / into /var/lib/database
baculaserver-fd JobId 7413:      /sys is a different filesystem. Will not descend from / into /sys
baculaserver-fd JobId 7413:      /dev is a different filesystem. Will not descend from / into /dev
20-Jan 00:14 baculaserver-sd JobId 7413: User specified spool size reached.
20-Jan 00:14 baculaserver-sd JobId 7413: Writing spooled data to Volume. Despooling 2,147,487,736 bytes ...
20-Jan 00:15 baculaserver-sd JobId 7413: Despooling elapsed time = 00:00:23, Transfer rate = 93.36 M bytes/second
...
...
20-Jan 00:29 baculaserver-sd JobId 7413: Spooling data again ...
20-Jan 00:31 baculaserver-sd JobId 7413: User specified spool size reached.
20-Jan 00:31 baculaserver-sd JobId 7413: Writing spooled data to Volume. Despooling 2,147,487,766 bytes ...
20-Jan 00:32 baculaserver-sd JobId 7413: Despooling elapsed time = 00:00:26, Transfer rate = 82.59 M bytes/second
20-Jan 00:32 baculaserver-sd JobId 7413: Spooling data again ...
20-Jan 00:33 baculaserver-sd JobId 7413: User specified spool size reached.
20-Jan 00:33 baculaserver-sd JobId 7413: Writing spooled data to Volume. Despooling 2,147,487,768 bytes ...
20-Jan 00:34 baculaserver-sd JobId 7413: Error: block.c:569 Write error at 45:2749 on device "LTO4_1" (/dev/nst0). ERR=Input/output error.
20-Jan 00:34 baculaserver-sd JobId 7413: Error: Error writing final EOF to tape. This Volume may not be readable.
dev.c:1669 ioctl MTWEOF error on "LTO4_1" (/dev/nst0). ERR=Input/output error.
20-Jan 00:34 baculaserver-sd JobId 7413: End of medium on Volume "150ADU" Bytes=17,639,129,088 Blocks=273,423 at 20-Jan-2009 00:34.
20-Jan 00:35 baculaserver-dir JobId 7413: Using Volume "000019" from 'Scratch' pool.
20-Jan 00:35 baculaserver-sd JobId 7413: 3307 Issuing autochanger "unload slot 42, drive 0" command.
20-Jan 00:36 baculaserver-sd JobId 7413: 3304 Issuing autochanger "load slot 1, drive 0" command.
20-Jan 00:37 baculaserver-sd JobId 7413: 3305 Autochanger "load slot 1, drive 0", status is OK.
20-Jan 00:37 baculaserver-sd JobId 7413: 3301 Issuing autochanger "loaded? drive 0" command.
20-Jan 00:37 baculaserver-sd JobId 7413: 3302 Autochanger "loaded? drive 0", result is Slot 1.
20-Jan 00:37 baculaserver-sd JobId 7413: Wrote label to prelabeled Volume "000019" on device "LTO4_1" (/dev/nst0)
20-Jan 00:37 baculaserver-sd JobId 7413: New volume "000019" mounted on device "LTO4_1" (/dev/nst0) at 20-Jan-2009 00:37.
20-Jan 00:37 baculaserver-sd JobId 7413: Despooling elapsed time = 00:01:30, Transfer rate = 23.86 M bytes/second
20-Jan 00:37 baculaserver-sd JobId 7413: Spooling data again ...
20-Jan 00:39 baculaserver-sd JobId 7413: User specified spool size reached.
20-Jan 00:39 baculaserver-sd JobId 7413: Writing spooled data to Volume. Despooling 2,147,487,768 bytes ...
20-Jan 00:39 baculaserver-sd JobId 7413: Error: block.c:569 Write error at 5:2282 on device "LTO4_1" (/dev/nst0). ERR=Input/output error.
20-Jan 00:39 baculaserver-sd JobId 7413: Error: Error writing final EOF to tape. This Volume may not be readable.
dev.c:1669 ioctl MTWEOF error on "LTO4_1" (/dev/nst0). ERR=Input/output error.
20-Jan 00:39 baculaserver-sd JobId 7413: End of medium on Volume "000019" Bytes=2,147,088,384 Blocks=33,281 at 20-Jan-2009 00:39.
20-Jan 00:40 baculaserver-dir JobId 7413: Using Volume "000020" from 'Scratch' pool.
20-Jan 00:40 baculaserver-sd JobId 7413: 3307 Issuing autochanger "unload slot 1, drive 0" command.
20-Jan 00:41 baculaserver-sd JobId 7413: 3304 Issuing autochanger "load slot 2, drive 0" command.
20-Jan 00:42 baculaserver-sd JobId 7413: 3305 Autochanger "load slot 2, drive 0", status is OK.
20-Jan 00:42 baculaserver-sd JobId 7413: 3301 Issuing autochanger "loaded? drive 0" command.
20-Jan 00:42 baculaserver-sd JobId 7413: 3302 Autochanger "loaded? drive 0", result is Slot 2.
20-Jan 00:42 baculaserver-sd JobId 7413: Wrote label to prelabeled Volume "000020" on device "LTO4_1" (/dev/nst0)
20-Jan 00:42 baculaserver-sd JobId 7413: New volume "000020" mounted on device "LTO4_1" (/dev/nst0) at 20-Jan-2009 00:42.
20-Jan 00:42 baculaserver-sd JobId 7413: Despooling elapsed time = 00:00:26, Transfer rate = 82.59 M bytes/second
20-Jan 00:42 baculaserver-sd JobId 7413: Spooling data again ...
20-Jan 00:45 baculaserver-sd JobId 7413: User specified spool size reached.
20-Jan 00:45 baculaserver-sd JobId 7413: Writing spooled data to Volume. Despooling 2,147,487,768 bytes ...
20-Jan 00:45 baculaserver-sd JobId 7413: Despooling elapsed time = 00:00:27, Transfer rate = 79.53 M bytes/second
20-Jan 00:45 baculaserver-sd JobId 7413: Spooling data again ...
20-Jan 00:48 baculaserver-sd JobId 7413: User specified spool size reached.
20-Jan 00:48 baculaserver-sd JobId 7413: Writing spooled data to Volume. Despooling 2,147,487,768 bytes ...
20-Jan 00:49 baculaserver-sd JobId 7413: Error: block.c:569 Write error at 9:4563 on device "LTO4_1" (/dev/nst0). ERR=Input/output error.
20-Jan 00:49 baculaserver-sd JobId 7413: Error: Error writing final EOF to tape. This Volume may not be readable.
dev.c:1669 ioctl MTWEOF error on "LTO4_1" (/dev/nst0). ERR=Input/output error.
20-Jan 00:49 baculaserver-sd JobId 7413: End of medium on Volume "000020" Bytes=4,294,112,256 Blocks=66,562 at 20-Jan-2009 00:49.
20-Jan 00:50 baculaserver-dir JobId 7413: Using Volume "000021" from 'Scratch' pool.
20-Jan 00:50 baculaserver-sd JobId 7413: 3307 Issuing autochanger "unload slot 2, drive 0" command.
20-Jan 00:51 baculaserver-sd JobId 7413: 3304 Issuing autochanger "load slot 3, drive 0" command.
20-Jan 00:53 baculaserver-sd JobId 7413: Fatal error: 3992 Bad autochanger "load slot 3, drive 0": ERR=Child died from signal 15: Termination.
Results=mtx: Request Sense: Long Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=0 (Unknown?!)
mtx: Request Sense: Sense Key=No Sense
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 00
mtx: Request Sense: Additional Sense Qualifier = 00
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 4098 to 256 Failed
/dev/nst0: Input/output error
/dev/nst0: Input/output error
..
..
..
/dev/nst0: Input/output error
/dev/nst0: Input/output er
20-Jan 00:53 baculaserver-sd JobId 7413: Fatal error: spool.c:294 Fatal append error on device "LTO4_1" (/dev/nst0): ERR=Job BACKUPSRV.2009-01-19_22.40.19 canceled while waiting for mount on Storage Device "LTO4_1" (/dev/nst0).

20-Jan 00:53 baculaserver-sd JobId 7413: Despooling elapsed time = 00:04:45, Transfer rate = 7.535 M bytes/second
20-Jan 00:53 baculaserver-sd JobId 7413: Job write elapsed time = 00:35:21, Transfer rate = 12.13 M bytes/second
20-Jan 00:53 baculaserver-fd JobId 7413: Fatal error: backup.c:892 Network send error to SD. ERR=Connection reset by peer
20-Jan 00:53 baculaserver-fd JobId 7413: Error: bsock.c:306 Write error sending 65536 bytes to Storage daemon:baculaserver.fbn-nbf.local:9103: ERR=Connection reset by peer
20-Jan 00:53 baculaserver-dir JobId 7413: Error: Bacula baculaserver-dir 2.2.6 (10Nov07): 20-Jan-2009 00:53:28
Build OS:               x86_64-unknown-linux-gnu redhat Enterprise release
JobId:                  7413
Job:                    BACKUPSRV.2009-01-19_22.40.19
Backup Level:           Incremental, since=2009-01-18 07:00:00
Client:                 "baculaserver-fd" 2.2.6 (10Nov07) x86_64-unknown-linux-gnu,redhat,Enterprise release
FileSet:                "LinuxServerSet" 2008-03-03 22:40:00
Pool:                   "Incrementals" (From Job IncPool override)
Storage:                "TS3200_1_DRV1" (From Pool resource)
Scheduled time:         19-Jan-2009 22:40:00
Start time:             20-Jan-2009 00:12:18
End time:               20-Jan-2009 00:53:28
Elapsed time:           41 mins 10 secs
Priority:               10
FD Files Written:       2,643
SD Files Written:       2,643
FD Bytes Written:       25,745,186,473 (25.74 GB)
SD Bytes Written:       25,745,186,392 (25.74 GB)
Rate:                   10423.2 KB/s
Software Compression:   None
VSS:                    no
Encryption:             no
Volume name(s):         150ADU|000019|000020
Volume Session Id:      832
Volume Session Time:    1229521617
Last Volume Bytes:      64,512 (64.51 KB)
Non-fatal FD errors:    1
SD Errors:              0
FD termination status: Error
SD termination status: Error
Termination:            *** Backup Error ***

Is this due to dirty tape drive head? Thanks for your advice.

Win

------------------------------------------------------------------------------
This SF.net email is sponsored by:
SourcForge Community
SourceForge wants to tell your story.
http://p.sf.net/sfu/sf-spreadtheword

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

[Bacula-users] New volumes put into "Full" status in succession from single backup