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@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
