On Wednesday 20 September 2006 17:26, [EMAIL PROTECTED] wrote: > 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!
What I see here looks perfectly normal from a Bacula stand point, with the exception that I am not completely sure why jobs are failing because they want to load tape 000013 into drive 0. That could probably be determined by setting debug at about 50 and looking at the output from the reservation system. First, it appears that Volume 000055 is in drive 0 and being used. It is also needed in drive 1 (why I don't know), so Bacula finds itself in a deadlock situation and asks for operator intervention. Apparently, your jobs are setup to request the same tape on two different drives. This will give a conflict. Second, it is normal that it appears that two jobs are writing different volumes on drive 1. The first job was writing 000052 when it filled and is blocked waiting for the other job to mount the tape 000055 and get it going so both jobs are showing data that in the first case is out of date, and in the second case, in the future (what it wants). If you were to mount 000055 on drive 1 both jobs would show that they are writing to it. > > > 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 > ------------------------------------------------------------------------- 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
