Hi, ok, I captured some debug output regarding the issue when the SD can't detect a usable volume in the tape drive.
This only happens (in my installations) when the pool requested is changed. In this case, the full backups from one pool ran fine, and the incremental backups for the week started. The former use the pool "Archive", the latter the "Daily" one. The state in which I found the system was as follows: - A usable tape from pool "Daily" had been loaded into the libraries tape drive (coming from slot 8, having the name 000974L2). This volume was selected according to the retention periods, and loading obviously worked. The debug trace output (this one at level 1000, I believe) shows the following when I usse a mount command: bacula1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=8 Volume=000974L2 bacula1-sd: reserve.c:406-0 jid=7452 find_vol=000974L2 found=1 bacula1-sd: reserve.c:181-0 jid=7452 List from find_volume: 000974L2 at 8e2fef0 on device "U LTRIUM" (/dev/st0) bacula1-sd: reserve.c:538-0 jid=7452 Vol=000974L2 on same dev. bacula1-sd: reserve.c:313-0 jid=7452 reserve_volume 000974L2 bacula1-sd: reserve.c:181-0 jid=7452 List from begin reserve_volume: 000974L2 at 8e2fef0 on device "ULTRIUM" (/dev/st0) bacula1-sd: reserve.c:181-0 jid=7452 List from end new volume: 000974L2 at 8e2fef0 on device "ULTRIUM" (/dev/st0) bacula1-sd: mount.c:122-0 After find_next_append. Vol=000974L2 Slot=8 Parts=0 bacula1-sd: autochanger.c:217-0 After changer, status=0 bacula1-sd: mount.c:142-0 autoload_dev returns 1 bacula1-sd: mount.c:158-0 Ask=0 autochanger=1 bacula1-sd: mount.c:168-0 want vol=000974L2 bacula1-sd: dev.c:303-0 open dev: type=2 dev_name="ULTRIUM" (/dev/st0) vol=000974L2 mode=OPE N_READ_WRITE bacula1-sd: dev.c:353-0 Open dev: device is tape bacula1-sd: autochanger.c:299-0 Locking changer AutoChanger bacula1-sd: autochanger.c:269-0 Run program=/etc/bacula/mtx-changer /dev/sg1 loaded 8 /dev/s t0 0 bacula1-sd: pythonlib.c:237-0 No startup module. bacula1-sd: mem_pool.c:377-0 garbage collect memory pool bacula1-sd: autochanger.c:271-0 run_prog: /etc/bacula/mtx-changer /dev/sg1 loaded 8 /dev/st0 0 stat=0 result=8 bacula1-sd: autochanger.c:308-0 Unlocking changer AutoChanger bacula1-sd: dev.c:368-0 Try open "ULTRIUM" (/dev/st0) mode=OPEN_READ_WRITE bacula1-sd: dev.c:390-0 Rewind after open bacula1-sd: dev.c:400-0 Rewind error on "ULTRIUM" (/dev/st0) close: ERR=Input/output error bacula1-sd: dev.c:434-0 dev.c:433 Unable to open device "ULTRIUM" (/dev/st0): ERR=Input/outp ut error bacula1-sd: dev.c:442-0 open dev: tape -1 opened bacula1-sd: dev.c:317-0 preserve=0x0 fd=-1 bacula1-sd: dev.c:303-0 open dev: type=2 dev_name="ULTRIUM" (/dev/st0) vol=000974L2 mode=OPE N_READ_WRITE bacula1-sd: dev.c:353-0 Open dev: device is tape bacula1-sd: autochanger.c:299-0 Locking changer AutoChanger bacula1-sd: autochanger.c:269-0 Run program=/etc/bacula/mtx-changer /dev/sg1 loaded 8 /dev/s t0 0 bacula1-sd: autochanger.c:271-0 run_prog: /etc/bacula/mtx-changer /dev/sg1 loaded 8 /dev/st0 0 stat=0 result=8 bacula1-sd: autochanger.c:308-0 Unlocking changer AutoChanger bacula1-sd: dev.c:368-0 Try open "ULTRIUM" (/dev/st0) mode=OPEN_READ_WRITE bacula1-sd: dev.c:390-0 Rewind after open bacula1-sd: dev.c:400-0 Rewind error on "ULTRIUM" (/dev/st0) close: ERR=Input/output error **** Here I sense a problem *** bacula1-sd: dev.c:434-0 dev.c:433 Unable to open device "ULTRIUM" (/dev/st0): ERR=Input/outp ut error bacula1-sd: dev.c:442-0 open dev: tape -1 opened bacula1-sd: dev.c:317-0 preserve=0x0 fd=-1 bacula1-sd: mount.c:185-0 open_device failed: ERR=dev.c:433 Unable to open device "ULTRIUM" (/dev/st0): ERR=Input/output error bacula1-sd: mount.c:84-0 mount_next_vol retry=7 bacula1-sd: jcr.c:603-0 OnEntry JobStatus=R set=M bacula1-sd: jcr.c:623-0 OnExit JobStatus=M set=M bacula1-sd: wait.c:65-0 Enter blocked=BST_DOING_ACQUIRE bacula1-sd: bnet.c:666-0 who=client host=127.0.0.1 port=36643 bacula1-sd: dircmd.c:172-0 Conn: Hello Director bacula1-dir calling bacula1-sd: dircmd.c:185-0 Got a DIR connection bacula1-sd: jcr.c:603-0 OnEntry JobStatus=bacula1-sd: jcr.c:623-0 OnExit JobStatus=C set=C bacula1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 bacula1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL PROTECTED] -dir> ssl=0 bacula1-sd: cram-md5.c:152-0 sending resp to challenge: g7dWZ8RBojUi29hDj6dRHC bacula1-sd: dircmd.c:207-0 Message channel init completed. bacula1-sd: dircmd.c:214-0 <dird: setdebug=1000 trace=1 bacula1-sd: dircmd.c:228-0 Do command: setdebug= bacula1-sd: dircmd.c:277-0 setdebug_cmd: setdebug=1000 trace=1 bacula1-sd: pythonlib.c:237-0 No startup module. bacula1-sd: job.c:326-0 stored_free_jcr JobId=0 bacula1-sd: message.c:415-0 Close_msg jcr=8e365c8 bacula1-sd: message.c:415-0 Close_msg jcr=0 bacula1-sd: message.c:427-0 ===Begin close msg resource at 8e18080 bacula1-sd: message.c:511-0 Done walking message chain. bacula1-sd: message.c:518-0 ===End close msg resource bacula1-sd: mem_pool.c:377-0 garbage collect memory pool bacula1-sd: bnet.c:666-0 who=client host=127.0.0.1 port=36643 bacula1-sd: dircmd.c:172-0 Conn: Hello Director bacula1-dir calling bacula1-sd: dircmd.c:185-0 Got a DIR connection bacula1-sd: jcr.c:603-0 OnEntry JobStatus=bacula1-sd: jcr.c:623-0 OnExit JobStatus=C set=C bacula1-sd: dircmd.c:198-0 stored in start_job bacula1-sd: watchdog.c:193-0 Registered watchdog 8e33e08, interval 600 one shot bacula1-sd: btimers.c:179-0 Start bsock timer 8e360e8 tid=48006 for 600 secs at 1194347791 bacula1-sd: cram-md5.c:73-0 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 bacula1-sd: cram-md5.c:133-0 cram-get received: auth cram-md5 <[EMAIL PROTECTED] -dir> ssl=0 bacula1-sd: cram-md5.c:152-0 sending resp to challenge: aHVb61lkzm+5nysdBnl32D bacula1-sd: btimers.c:193-0 Stop bsock timer 8e360e8 tid=48006 at 1194347791. bacula1-sd: watchdog.c:213-0 Unregistered watchdog 8e33e08 bacula1-sd: dircmd.c:207-0 Message channel init completed. bacula1-sd: dircmd.c:214-0 <dird: mount AutoChanger drive=-1 slot=8 bacula1-sd: dircmd.c:228-0 Do command: mount bacula1-sd: dircmd.c:590-0 Try changer device ULTRIUM bacula1-sd: dircmd.c:606-0 Found changer device ULTRIUM bacula1-sd: dircmd.c:619-0 Found device ULTRIUM bacula1-sd: block.c:133-0 Returning new block=8e358b0 bacula1-sd: acquire.c:666-0 JobId=0 enter attach_dcr_to_dev bacula1-sd: dircmd.c:650-0 mount cmd blocked=2 bacula1-sd: dircmd.c:654-0 Waiting for mount. Attempting to wake thread bacula1-sd: dircmd.c:659-0 JobId=0 broadcast wait_device_release bacula1-sd: wait.c:105-0 Wokeup from sleep on device stat=0 blocked=BST_MOUNT bacula1-sd: acquire.c:677-0 JobId=0 enter detach_dcr_from_dev bacula1-sd: wait.c:184-0 set BST_DOING_ACQUIRE bacula1-sd: wait.c:186-0 Exit blocked=BST_DOING_ACQUIRE bacula1-sd: block.c:170-0 free_block buffer 8e6fff8 bacula1-sd: askdir.c:596-0 Back from wait_for_sysop stat=4 bacula1-sd: block.c:172-0 free_block block 8e358b0 bacula1-sd: askdir.c:619-0 Someone woke me for device "ULTRIUM" (/dev/st0) bacula1-sd: record.c:221-0 Enter free_record. bacula1-sd: jcr.c:603-0 OnEntry JobStatus=M set=R bacula1-sd: record.c:225-0 Data buf is freed. bacula1-sd: jcr.c:623-0 OnExit JobStatus=R set=R bacula1-sd: record.c:227-0 Leave free_record. bacula1-sd: askdir.c:626-0 leave dir_ask_sysop_to_mount_volume bacula1-sd: mount.c:101-0 mount_next_volume release=1 bacula1-sd: dev.c:1826-0 Clear volhdr vol= bacula1-sd: mount.c:611-0 release_volume bacula1-sd: mount.c:110-0 Before dir_find_next_appendable_volume. bacula1-sd: askdir.c:256-0 dir_find_next_appendable_volume bacula1-sd: askdir.c:271-0 >dird: CatReq Job=CALLMANAGER1-Daily.2007-11-05_21.00.04 FindMedi a=1 pool_name=Daily media_type=LT02 bacula1-sd: askdir.c:182-0 <dird 1000 OK VolName=000974L2 VolJobs=0 VolFiles=0 VolBlocks=0 V olBytes=64512 VolMounts=0 VolErrors=0 VolWrites=0 MaxVolBytes=0 VolCapacityBytes=0 VolStatus =Append Slot=8 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 MediaId=66 bacula1-sd: askdir.c:204-0 do_reqest_vol_info return true slot=8 Volume=000974L2 bacula1-sd: reserve.c:406-0 jid=7452 find_vol=000974L2 found=1 bacula1-sd: mem_pool.c:568-0 max_size=512 bacula1-sd: reserve.c:181-0 jid=7452 List from find_volume: 000974L2 at 8e2fef0 on device "U LTRIUM" (/dev/st0) bacula1-sd: reserve.c:538-0 jid=7452 Vol=000974L2 on same dev. bacula1-sd: askdir.c:290-0 dir_find_next_appendable_volume return true bacula1-sd: reserve.c:313-0 jid=7452 reserve_volume 000974L2 bacula1-sd: mem_pool.c:568-0 max_size=512 bacula1-sd: reserve.c:181-0 jid=7452 List from begin reserve_volume: 000974L2 at 8e2fef0 on device "ULTRIUM" (/dev/st0) bacula1-sd: mem_pool.c:568-0 max_size=512 bacula1-sd: reserve.c:181-0 jid=7452 List from end new volume: 000974L2 at 8e2fef0 on device "ULTRIUM" (/dev/st0) bacula1-sd: mount.c:122-0 After find_next_append. Vol=000974L2 Slot=8 Parts=0 bacula1-sd: autochanger.c:145-0 Want changer slot=8 bacula1-sd: autochanger.c:217-0 After changer, status=0 bacula1-sd: mount.c:142-0 autoload_dev returns 1 bacula1-sd: mount.c:158-0 Ask=0 autochanger=1 bacula1-sd: mount.c:168-0 want vol=000974L2 I've marked where I think the problem occurs. Can someone confirm that the rewind fails where the problems happens? Arno 05.11.2007 16:21,, Arno Lehmann wrote:: > Hi, > > 05.11.2007 13:53,, Shon Stephens wrote:: >> I have an autochanger with 12 tapes. I issue the label barcodes command >> and it cycles through the tapes in the changer and then does the following: >> >> 3307 Issuing autochanger "unload slot 11, drive 0" command. >> 3304 Issuing autochanger "load slot 12, drive 0" command. >> 3305 Autochanger "load slot 12, drive 0", status is OK. >> 3301 Issuing autochanger "loaded? drive 0" command. >> 3302 Autochanger "loaded? drive 0", result: nothing loaded. >> 3000 OK label. VolBytes=64512 DVD=0 Volume="A00012" Device="Ultrium-TD3" >> (/dev/rmt/0cbn) >> Catalog record for Volume "A00012", Slot 12 successfully created. >> >> *release >> The defined Storage resources are: >> 1: Mentora_Files >> 2: Exabyte_224 >> Select Storage resource (1-2): 2 >> 3301 Issuing autochanger "loaded? drive 0" command. >> 3302 Autochanger "loaded? drive 0", result: nothing loaded. >> 3921 Device "Ultrium-TD3" (/dev/rmt/0cbn) already released. >> >> This is where Bacula then "loses" the 12th tape. I can't get Bacula to >> even recognize that its in the drive and needs to be unloaded. Does >> anyone know what the issue might be? > > Unfortunately, I don't have the solution to this. I face the same > issue, and I can not always reproduce it, which makes it a bit hard to > analyze (available time is an issue here, too... :-) > > My workaround is to unmount the drive from Bacula, use mtx to unload > the tape and load the tape requested, and mount from Bacula again. > > Until now, that has worked every time. > > As it is, I'm not even sure this is an issue purely inside Bacula, > because a) the autochanger or drive seem to need the extra kick of > unloading / reloading a tape, and b) not all the installations I > support seem to show this behavior. It might be OS or hardware dependent. > > For me, the workaround is ok for a while because where it happens > tapes are not always needed to be changed. Also, the issue *seems* to > happen only when a tape from a different pool than the one currently > loaded is needed (which points to Bacula, not the environment). > > All this is only an impression, not the result of careful observation, > by the way. > > Arno > >> -Shon >> >> >> ------------------------------------------------------------------------ >> >> ------------------------------------------------------------------------- >> This SF.net email is sponsored by: Splunk Inc. >> Still grepping through log files to find problems? Stop. >> Now Search log events and configuration files using AJAX and a browser. >> Download your FREE copy of Splunk now >> http://get.splunk.com/ >> >> >> ------------------------------------------------------------------------ >> >> _______________________________________________ >> Bacula-users mailing list >> Bacula-users@lists.sourceforge.net >> https://lists.sourceforge.net/lists/listinfo/bacula-users > -- Arno Lehmann IT-Service Lehmann www.its-lehmann.de ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/ _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
