I'm running into a situation where Bacula wants a given volume to be
in one drive of our autochanger, and it doesn't seem to find the volume when
it's already in the other drive. I saw similar situations under Bacula 1.38.9,
but I've since upgraded to Bacula 1.38.11 (for the -dir and -sd, clients are
still at
1.38.9), under Linux (FC1), with a 23-slot, 2 drive autochanger and mysql5.
Most recently, I changed many tapes in the autochanger, restarted bacula, and
backups have been working fine (with many tape changes) for about a week.
During this period, there were times when each drive was in use individually,
and when both drives were in use. Since restarting bacula, there have been no
manual tape changes, no manual tape movements (via the autochanger or using
mtx), and I have not run "update slots" or mounted/umounted volumes within
bacula. All backups for the last week have been initiated by bacula
automatically, and there have been no restores in this time period.
Now, one job is hung because bacula wants tape "000055" in
drive 1 when it's presently in drive 0:
20-Sep 06:43 parthenon-sd: Please mount Volume "000055" on Storage
Device "Drive-1"
(/dev/tape1) for Job athena1-inc.2006-09-19_23.11.02
Other jobs failed because bacula wanted to load tape 000013 into drive 0, when
that was already occupied.
Please see output from bconsole below, and note that bacula claims that it's
writing to both tapes 000052 and 000055 in the same volume!
I am happy to supply config files or additional debugging information.
Thanks,
Mark
-------------------------------------------------------------------------
19-Sep 23:09 parthenon-dir: Start Backup JobId 1148,
Job=sbia-full.2006-09-19_23.09.01
19-Sep 23:09 parthenon-sd: sbia-full.2006-09-19_23.09.01 Fatal error:
acquire.c:263 Wanted Volume "000013", but device "Drive-0" (/dev/tape0) is busy
writing on "000055" .
19-Sep 23:09 sbia-fd: sbia-full.2006-09-19_23.09.01 Fatal error: job.c:1616 Bad
response to Append Data command. Wanted 3000 OK data
, got 3903 Error append data
19-Sep 23:09 parthenon-dir: sbia-full.2006-09-19_23.09.01 Error: Bacula 1.38.11
(28Jun06): 19-Sep-2006 23:09:02
JobId: 1148
Job: sbia-full.2006-09-19_23.09.01
Backup Level: Full
Client: "sbia-fd" i686-pc-linux-gnu,redhat,7.2
FileSet: "Full Set" 2006-07-27 14:15:10
Pool: "Full"
Storage: "pv132t"
Scheduled time: 19-Sep-2006 23:09:00
Start time: 19-Sep-2006 23:09:02
End time: 19-Sep-2006 23:09:02
Elapsed time: 0 secs
Priority: 10
FD Files Written: 0
SD Files Written: 0
FD Bytes Written: 0 (0 B)
SD Bytes Written: 0 (0 B)
Rate: 0.0 KB/s
Software Compression: None
Volume name(s):
Volume Session Id: 51
Volume Session Time: 1158351490
Last Volume Bytes: 325,491,826,996 (325.4 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: Error
SD termination status: Error
Termination: *** Backup Error ***
19-Sep 23:09 parthenon-sd: cbic-full.2006-09-19_23.09.00 Fatal error:
acquire.c:263 Wanted Volume "000013", but device "Drive-1" (/dev/tape1) is busy
writing on "000052" .
19-Sep 23:07 cbic-fd: cbic-full.2006-09-19_23.09.00 Fatal error: job.c:1617 Bad
response to Append Data command. Wanted 3000 OK data
, got 3903 Error append data
19-Sep 23:09 parthenon-dir: cbic-full.2006-09-19_23.09.00 Error: Bacula 1.38.11
(28Jun06): 19-Sep-2006 23:09:03
JobId: 1147
Job: cbic-full.2006-09-19_23.09.00
Backup Level: Full
Client: "cbic-fd" sparc-sun-solaris2.8,solaris,5.8
FileSet: "Full Set" 2006-07-27 14:15:10
Pool: "Full"
Storage: "pv132t"
Scheduled time: 19-Sep-2006 23:09:00
Start time: 19-Sep-2006 23:09:02
End time: 19-Sep-2006 23:09:03
Elapsed time: 1 sec
Priority: 10
FD Files Written: 0
SD Files Written: 0
FD Bytes Written: 0 (0 B)
SD Bytes Written: 0 (0 B)
Rate: 0.0 KB/s
Software Compression: None
Volume name(s):
Volume Session Id: 50
Volume Session Time: 1158351490
Last Volume Bytes: 325,491,826,996 (325.4 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: Error
SD termination status: Error
Termination: *** Backup Error ***
athena1-fd: Disallowed filesystem. Will not descend into /sbia/home
athena1-fd: Disallowed filesystem. Will not descend into /sbia/sbiaprj
athena1-fd: Disallowed filesystem. Will not descend into /sbia/comp_space
athena1-fd: Disallowed filesystem. Will not descend into /sbia/mobiledev
athena1-fd: Disallowed filesystem. Will not descend into /websbia
athena1-fd: Disallowed filesystem. Will not descend into /labmanpages
athena1-fd: Disallowed filesystem. Will not descend into /nilab
athena1-fd: Disallowed filesystem. Will not descend into /CIFS
19-Sep 23:26 parthenon-sd: Committing spooled data to Volume "000052".
Despooling 1,040,778,475 bytes ...
19-Sep 23:27 parthenon-sd: End of Volume "000052" at 330:6296 on device
"Drive-1" (/dev/tape1). Write of 64512 bytes got -1.
19-Sep 23:27 parthenon-sd: Re-read of last block succeeded.
19-Sep 23:27 parthenon-sd: End of medium on Volume "000052"
Bytes=330,057,228,267 Blocks=5,116,218 at 19-Sep-2006 23:27.
19-Sep 23:27 parthenon-sd: 3301 Issuing autochanger "loaded drive 1" command.
19-Sep 23:27 parthenon-sd: 3302 Autochanger "loaded drive 1", result is Slot 21.
19-Sep 23:27 parthenon-sd: 3307 Issuing autochanger "unload slot 21, drive 1"
command.
19-Sep 23:28 parthenon-sd: Job athena1-inc.2006-09-19_23.11.02 waiting to
reserve a device.
19-Sep 23:43 parthenon-sd: athena1-inc.2006-09-19_23.11.02 Warning: Volume
"000055" is in use by device "Drive-0" (/dev/tape0)
19-Sep 23:43 parthenon-sd: Please mount Volume "000055" on Storage Device
"Drive-1" (/dev/tape1) for Job athena1-inc.2006-09-19_23.11.02
19-Sep 23:45 parthenon-sd: User specified spool size reached.
19-Sep 23:45 parthenon-sd: Writing spooled data to Volume. Despooling
63,383,795,207 bytes ...
20-Sep 00:43 parthenon-sd: Please mount Volume "000055" on Storage Device
"Drive-1" (/dev/tape1) for Job athena1-inc.2006-09-19_23.11.02
20-Sep 00:54 parthenon-dir: Begin pruning Jobs.
20-Sep 00:54 parthenon-dir: No Jobs found to prune.
20-Sep 00:54 parthenon-dir: Begin pruning Files.
20-Sep 00:54 parthenon-dir: No Files found to prune.
20-Sep 00:54 parthenon-dir: End auto prune.
20-Sep 02:43 parthenon-sd: Please mount Volume "000055" on Storage Device
"Drive-1" (/dev/tape1) for Job athena1-inc.2006-09-19_23.11.02
20-Sep 06:43 parthenon-sd: Please mount Volume "000055" on Storage Device
"Drive-1" (/dev/tape1) for Job athena1-inc.2006-09-19_23.11.02
stat dir
parthenon-dir Version: 1.38.11 (28 June 2006) i686-pc-linux-gnu redhat (Yarrow)
Daemon started 15-Sep-06 16:18, 58 Jobs run since started.
Scheduled Jobs:
Level Type Pri Scheduled Name Volume
===================================================================================
Incremental Backup 10 20-Sep-06 23:05 parthenon-inc 000055
Incremental Backup 10 20-Sep-06 23:07 delphi-inc 000055
Incremental Backup 10 20-Sep-06 23:07 braid2-inc 000055
Incremental Backup 10 20-Sep-06 23:07 olympus-inc 000055
Incremental Backup 10 20-Sep-06 23:09 cbic-inc 000055
Incremental Backup 10 20-Sep-06 23:09 sbia-inc 000055
Full Backup 11 20-Sep-06 23:10 BackupCatalog 000055
Differential Backup 10 20-Sep-06 23:11 rodos-inc 000055
Differential Backup 10 20-Sep-06 23:11 athena1-inc 000055
Differential Backup 10 20-Sep-06 23:11 smyrna-inc 000055
Incremental Backup 10 20-Sep-06 23:13 athena2-inc 000055
Incremental Backup 10 20-Sep-06 23:15 athens-inc 000055
Incremental Backup 10 20-Sep-06 23:15 athena3-inc 000055
====
Running Jobs:
Console connected at 15-Sep-06 16:39
JobId Level Name Status
======================================================================
1097 Full BackupCatalog.2006-09-15_23.10.00 is waiting for higher priority
jobs to finish
1101 Full athena2-inc.2006-09-15_23.13.00 is running
1110 Full BackupCatalog.2006-09-16_23.10.00 has been canceled
1114 Increme athena2-inc.2006-09-16_23.13.00 has been canceled
1123 Full BackupCatalog.2006-09-17_23.10.00 has been canceled
1127 Increme athena2-inc.2006-09-17_23.13.00 has been canceled
1136 Full BackupCatalog.2006-09-18_23.10.00 has been canceled
1140 Increme athena2-inc.2006-09-18_23.13.00 is waiting on max Job jobs
1149 Full BackupCatalog.2006-09-19_23.10.00 is waiting execution
1152 Increme athena1-inc.2006-09-19_23.11.02 is waiting for a mount request
1153 Increme athena2-inc.2006-09-19_23.13.00 is waiting on max Job jobs
====
Terminated Jobs:
JobId Level Files Bytes Status Finished Name
========================================================================
1144 Incr 71 34,990,253 OK 19-Sep-06 23:07 delphi-inc
1145 Incr 328 116,234,736 OK 19-Sep-06 23:07 olympus-inc
1148 Full 0 0 Error 19-Sep-06 23:09 sbia-full
1147 Full 0 0 Error 19-Sep-06 23:09 cbic-full
1151 Incr 34 2,037,500 OK 19-Sep-06 23:11 smyrna-inc
1150 Incr 150 1,408,507 OK 19-Sep-06 23:11 rodos-inc
1146 Incr 38 92,536,705 OK 19-Sep-06 23:12 braid2-inc
1154 Incr 151 1,560,798 OK 19-Sep-06 23:16 athens-inc
1155 Incr 13,744 16,255,238,391 OK 20-Sep-06 00:38 athena3-inc
1143 Incr 3,098 83,813,468,499 OK 20-Sep-06 00:54 parthenon-inc
====
stat stor
Automatically selected Storage: pv132t
Connecting to Storage daemon pv132t at parthenon:9103
parthenon-sd Version: 1.38.11 (28 June 2006) i686-pc-linux-gnu redhat (Yarrow)
Daemon started 15-Sep-06 16:18, 54 Jobs run since started.
Running Jobs:
Writing: Full Backup job athena2-inc JobId=1101 Volume="000052"
pool="Incremental" device=""Drive-1" (/dev/tape1)"
Files=1,101,955 Bytes=2,127,959,201,866 Bytes/sec=5,529,076
FDReadSeqNo=41,046,858 in_msg=38116667 out_msg=5 fd=23
Writing: Incremental Backup job athena1-inc JobId=1152 Volume="000055"
pool="Incremental" device=""Drive-1" (/dev/tape1)"
Files=6,715 Bytes=1,039,599,385 Bytes/sec=25,602
FDReadSeqNo=71,541 in_msg=52627 out_msg=5 fd=19
====
Jobs waiting to reserve a drive:
====
Terminated Jobs:
JobId Level Files Bytes Status Finished Name
======================================================================
1144 Incr 71 34,997,899 OK 19-Sep-06 23:07 delphi-inc
1145 Incr 328 116,277,953 OK 19-Sep-06 23:07 olympus-inc
1148 Full 0 0 Error 19-Sep-06 23:09 sbia-full
1147 Full 0 0 Error 19-Sep-06 23:09 cbic-full
1151 Incr 34 2,040,365 OK 19-Sep-06 23:11 smyrna-inc
1150 Incr 150 1,421,561 OK 19-Sep-06 23:11 rodos-inc
1146 Incr 38 92,540,000 OK 19-Sep-06 23:12 braid2-inc
1154 Incr 151 1,574,127 OK 19-Sep-06 23:16 athens-inc
1155 Incr 13,744 16,257,325,385 OK 20-Sep-06 00:38 athena3-inc
1143 Incr 3,098 83,813,936,494 OK 20-Sep-06 00:54 parthenon-inc
====
Device status:
Autochanger "pv132t" with devices:
"Drive-0" (/dev/tape0)
"Drive-1" (/dev/tape1)
Device "Drive-0" (/dev/tape0) is mounted with Volume="000055" Pool="Incremental"
Slot 22 is loaded in drive 0.
Total Bytes=100,277,259,891 Blocks=1,554,399 Bytes/block=64,511
Positioned at File=101 Block=0
Device "Drive-1" (/dev/tape1) is not open or does not exist.
Device is BLOCKED waiting for media.
Drive 1 is not loaded.
====
In Use Volume status:
====
Data spooling: 2 active jobs, 64,424,509,158 bytes; 47 total jobs,
113,764,774,564 max bytes/job.
Attr spooling: 2 active jobs, 0 bytes; 47 total jobs, 776,686,922 max bytes.
stat clients
Automatically selected Storage: pv132t
Connecting to Storage daemon pv132t at parthenon:9103
parthenon-sd Version: 1.38.11 (28 June 2006) i686-pc-linux-gnu redhat (Yarrow)
Daemon started 15-Sep-06 16:18, 54 Jobs run since started.
Running Jobs:
Writing: Full Backup job athena2-inc JobId=1101 Volume="000052"
pool="Incremental" device=""Drive-1" (/dev/tape1)"
Files=1,101,955 Bytes=2,127,959,201,866 Bytes/sec=5,528,976
FDReadSeqNo=41,046,858 in_msg=38116667 out_msg=5 fd=23
Writing: Incremental Backup job athena1-inc JobId=1152 Volume="000055"
pool="Incremental" device=""Drive-1" (/dev/tape1)"
Files=6,715 Bytes=1,039,599,385 Bytes/sec=25,597
FDReadSeqNo=71,541 in_msg=52627 out_msg=5 fd=19
====
Jobs waiting to reserve a drive:
====
Terminated Jobs:
JobId Level Files Bytes Status Finished Name
======================================================================
1144 Incr 71 34,997,899 OK 19-Sep-06 23:07 delphi-inc
1145 Incr 328 116,277,953 OK 19-Sep-06 23:07 olympus-inc
1148 Full 0 0 Error 19-Sep-06 23:09 sbia-full
1147 Full 0 0 Error 19-Sep-06 23:09 cbic-full
1151 Incr 34 2,040,365 OK 19-Sep-06 23:11 smyrna-inc
1150 Incr 150 1,421,561 OK 19-Sep-06 23:11 rodos-inc
1146 Incr 38 92,540,000 OK 19-Sep-06 23:12 braid2-inc
1154 Incr 151 1,574,127 OK 19-Sep-06 23:16 athens-inc
1155 Incr 13,744 16,257,325,385 OK 20-Sep-06 00:38 athena3-inc
1143 Incr 3,098 83,813,936,494 OK 20-Sep-06 00:54 parthenon-inc
====
Device status:
Autochanger "pv132t" with devices:
"Drive-0" (/dev/tape0)
"Drive-1" (/dev/tape1)
Device "Drive-0" (/dev/tape0) is mounted with Volume="000055" Pool="Incremental"
Slot 22 is loaded in drive 0.
Total Bytes=100,277,259,891 Blocks=1,554,399 Bytes/block=64,511
Positioned at File=101 Block=0
Device "Drive-1" (/dev/tape1) is not open or does not exist.
Device is BLOCKED waiting for media.
Drive 1 is not loaded.
====
In Use Volume status:
====
Data spooling: 2 active jobs, 64,424,509,158 bytes; 47 total jobs,
113,764,774,564 max bytes/job.
Attr spooling: 2 active jobs, 0 bytes; 47 total jobs, 776,686,922 max bytes.
-------------------------------------------------------------------------
----
Mark Bergman [EMAIL PROTECTED]
System Administrator
Section of Biomedical Image Analysis 215-662-7310
Department of Radiology, University of Pennsylvania
http://pgpkeys.pca.dfn.de:11371/pks/lookup?search=mark.bergman%40.uphs.upenn.edu
The information contained in this e-mail message is intended only for the
personal and confidential use of the recipient(s) named above. If the reader of
this message is not the intended recipient or an agent responsible for
delivering it to the intended recipient, you are hereby notified that you have
received this document in error and that any review, dissemination,
distribution, or copying of this message is strictly prohibited. If you have
received this communication in error, please notify us immediately by e-mail,
and delete the original message.
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys -- and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
