[Bacula-users] New volumes put into "Full" status in succession from single backup
2009-01-20 11:52:11
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
|
<Prev in Thread] |
Current Thread |
[Next in Thread>
|
- [Bacula-users] New volumes put into "Full" status in succession from single backup,
Win Htin <=
|
|
|