ok, here is a dump from -d400 that shows everything between starting the storage daemon and the not-working tape change.
When starting up, the drive has volume 306 from slot 7 loaded. This one is full and not appendable anymore. It recycles volume 300 and wants it loaded from slot 1. This is all correct. But then it stops. I don't see the actual error in there.
Log is attached.
Cheers,
Christian
bacula-sd: lex.c:148 Open config file: /etc/bacula/bacula-sd.conf bacula-sd: stored_conf.c:613 Inserting director res: Monitor bacula-sd: lex.c:148 Open config file: /etc/bacula/bacula-sd.conf bacula-sd: message.c:238 Copy message resource 0x80af3e0 to 0x80ae010 bart-sd: bsys.c:498 Could not open state file. sfd=-1 size=188: ERR=No such file or directory bart-sd: bpipe.c:291 Run program returning 0 bart-sd: bnet_server.c:83 Addresses host[ipv4:0.0.0.0:9103] bart-sd: stored.c:492 calling init_dev /dev/nst0 bart-sd: dev.c:242 init_dev: tape=2 dev_name=/dev/nst0 bart-sd: stored.c:494 SD init done /dev/nst0 bart-sd: autochanger.c:191 Locking changer GoceptChanger bart-sd: bpipe.c:291 Run program returning 0 bart-sd: autochanger.c:162 run_prog: /etc/bacula/mtx-changer /dev/sg3 loaded 0 /dev/nst0 0 stat=0 result=7
bart-sd: autochanger.c:200 Unlocking changer GoceptChanger bart-sd: stored.c:507 calling first_open_device "GoceptChangerDev" (/dev/nst0) bart-sd: device.c:246 start open_output_device() bart-sd: device.c:265 Opening device. bart-sd: dev.c:277 open dev: tape=2 dev_name="GoceptChangerDev" (/dev/nst0) vol= mode=OPEN_READ_ONLY bart-sd: dev.c:335 open dev: device is tape bart-sd: autochanger.c:191 Locking changer GoceptChanger bart-sd: bpipe.c:291 Run program returning 0 bart-sd: autochanger.c:162 run_prog: /etc/bacula/mtx-changer /dev/sg3 loaded 0 /dev/nst0 0 stat=0 result=7 bart-sd: autochanger.c:200 Unlocking changer GoceptChanger bart-sd: dev.c:358 Try open "GoceptChangerDev" (/dev/nst0) mode=OPEN_READ_ONLY nonblocking=2048 bart-sd: dev.c:397 openmode=3 OPEN_READ_ONLY bart-sd: dev.c:410 open dev: tape 8 opened bart-sd: device.c:272 open dev "GoceptChangerDev" (/dev/nst0) OK bart-sd: label.c:71 Enter read_volume_label device="GoceptChangerDev" (/dev/nst0) vol= dev_Vol=*NULL* bart-sd: dev.c:654 rewind_dev fd=8 "GoceptChangerDev" (/dev/nst0) bart-sd: label.c:138 Big if statement in read_volume_label bart-sd: block.c:879 Full read() in read_block_from_device() len=64512 bart-sd: block.c:943 Read device got 64512 bytes at 0:0 bart-sd: block.c:284 unser_block_header block_len=197 bart-sd: block.c:295 Read binbuf = 173 24 block_len=197 bart-sd: block.c:1065 At end of read block bart-sd: block.c:1078 Exit read_block read_len=64512 block_len=197 bart-sd: label.c:755 unser_vol_label Volume Label: Id : Bacula 1.0 immortal VerNo : 11 VolName : DailySet306 PrevVolName : VolFile : 0 LabelType : VOL_LABEL LabelSize : 161 PoolName : ChangerPool MediaType : DLT40 PoolType : Backup HostName : bart Date label written: 04-Aug-2005 23:21 bart-sd: reserve.c:118 new_volume DailySet306 bart-sd: label.c:206 Compare Vol names: VolName= hdr=DailySet306 bart-sd: label.c:222 Copy vol_name=DailySet306 Volume Label: Id : Bacula 1.0 immortal VerNo : 11 VolName : DailySet306 PrevVolName : VolFile : 0 LabelType : VOL_LABEL LabelSize : 161 PoolName : ChangerPool MediaType : DLT40 PoolType : Backup HostName : bart Date label written: 04-Aug-2005 23:21 bart-sd: label.c:227 Leave read_volume_label() VOL_OK bart-sd: dev.c:654 rewind_dev fd=8 "GoceptChangerDev" (/dev/nst0) bart-sd: bnet.c:1125 who=client host=10.1.1.40 port=36643 bart-sd: dircmd.c:157 Conn: Hello Director bart-dir calling bart-sd: dircmd.c:166 Start Dir Job bart-sd: cram-md5.c:52 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 bart-sd: cram-md5.c:68 Authenticate OK nzlihT+eh4/pO6sBenBjDB bart-sd: cram-md5.c:97 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 bart-sd: cram-md5.c:114 sending resp to challenge: t6+BM9/7J50H5hBkAz+ziD bart-sd: dircmd.c:187 Message channel init completed. bart-sd: dircmd.c:194 <dird: JobId=665 job=BaculaCatalog.2005-10-17_09.34.06 job_name=BaculaCatalog client_name=bart-fd type=66 level=70 FileSet=Catalog NoAttr=0 SpoolAttr=0 FileSetMD5=f7/JDyhoN90Uo7/wui/xgD SpoolData=1 WritePartAfterJob=0 PreferMountedVols=1 bart-sd: dircmd.c:208 Do command: JobId= bart-sd: job.c:70 <dird: JobId=665 job=BaculaCatalog.2005-10-17_09.34.06 job_name=BaculaCatalog client_name=bart-fd type=66 level=70 FileSet=Catalog NoAttr=0 SpoolAttr=0 FileSetMD5=f7/JDyhoN90Uo7/wui/xgD SpoolData=1 WritePartAfterJob=0 PreferMountedVols=1 bart-sd: job.c:123 >dird: 3000 OK Job SDid=1 SDtime=1129534433 Authorization=BJCD-HHDG-POPI-CHJB-JDKA-PCKP-PGDG-LBHL bart-sd: dircmd.c:194 <dird: use storage=GoceptChanger media_type=DLT40 pool_name=ChangerPool pool_type=Backup append=1 copy=0 stripe=0 bart-sd: dircmd.c:208 Do command: use storage= bart-sd: reserve.c:306 <dird: use storage=GoceptChanger media_type=DLT40 pool_name=ChangerPool pool_type=Backup append=1 copy=0 stripe=0 bart-sd: reserve.c:347 Storage=GoceptChanger media_type=DLT40 pool=ChangerPool pool_type=Backup bart-sd: reserve.c:349 Device=GoceptChanger bart-sd: reserve.c:515 Search res for GoceptChanger bart-sd: reserve.c:518 Try res=GoceptChangerDev bart-sd: reserve.c:534 Try changer res=GoceptChanger bart-sd: reserve.c:539 Try changer device GoceptChangerDev bart-sd: reserve.c:593 Found device GoceptChangerDev bart-sd: askdir.c:230 dir_find_next_appendable_volume bart-sd: askdir.c:242 >dird: CatReq Job=BaculaCatalog.2005-10-17_09.34.06 FindMedia=1 pool_name=ChangerPool media_type=DLT40 bart-sd: askdir.c:165 <dird 1000 OK VolName=DailySet300 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=3 VolErrors=0 VolWrites=2628536 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 bart-sd: askdir.c:187 do_reqest_vol_info return true slot=0 Volume=DailySet300 bart-sd: askdir.c:258 dir_find_next_appendable_volume return true bart-sd: reserve.c:118 new_volume DailySet300 bart-sd: reserve.c:610 Looking for Volume=DailySet300 bart-sd: reserve.c:708 reserve_append device is tape bart-sd: reserve.c:748 Not exact match have=DailySet306 want=DailySet300 bart-sd: reserve.c:711 reserve.c:746 Not exact match have=DailySet306 want=DailySet300 bart-sd: reserve.c:619 dev_name=GoceptChanger mediatype=DLT40 ok=0 bart-sd: reserve.c:515 Search res for GoceptChanger bart-sd: reserve.c:534 Try changer res=GoceptChanger bart-sd: reserve.c:539 Try changer device GoceptChangerDev bart-sd: reserve.c:593 Found device GoceptChangerDev bart-sd: reserve.c:708 reserve_append device is tape bart-sd: reserve.c:716 Inc reserve=1 bart-sd: reserve.c:619 dev_name=GoceptChanger mediatype=DLT40 ok=1 bart-sd: reserve.c:548 Device GoceptChanger opened. bart-sd: reserve.c:552 >dird changer: 3000 OK use device device=GoceptChangerDev bart-sd: dircmd.c:194 <dird: run bart-sd: dircmd.c:208 Do command: run bart-sd: job.c:137 Run_cmd: run bart-sd: job.c:155 BaculaCatalog.2005-10-17_09.34.06 waiting on FD to contact SD bart-sd: bnet.c:1125 who=client host=10.1.1.40 port=36643 bart-sd: dircmd.c:157 Conn: Hello Start Job BaculaCatalog.2005-10-17_09.34.06 bart-sd: job.c:197 Found Job BaculaCatalog.2005-10-17_09.34.06 bart-sd: cram-md5.c:52 send: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 bart-sd: cram-md5.c:68 Authenticate OK ay+ta58V4B+LZV/p96+gRD bart-sd: cram-md5.c:97 cram-get: auth cram-md5 <[EMAIL PROTECTED]> ssl=0 bart-sd: cram-md5.c:114 sending resp to challenge: 16M6n5+4k2/3XlZHU+Ik1C bart-sd: job.c:214 OK Authentication Job BaculaCatalog.2005-10-17_09.34.06 bart-sd: job.c:173 Running job BaculaCatalog.2005-10-17_09.34.06 bart-sd: fd_cmds.c:118 Start run Job=BaculaCatalog.2005-10-17_09.34.06 bart-sd: fd_cmds.c:135 <filed: append open session bart-sd: fd_cmds.c:212 Append open session: append open session bart-sd: fd_cmds.c:222 >filed: 3000 OK open ticket = 1 bart-sd: fd_cmds.c:135 <filed: append data 1 bart-sd: fd_cmds.c:174 Append data: append data 1 bart-sd: fd_cmds.c:176 <bfiled: append data 1 bart-sd: append.c:47 Start append data. bart-sd: acquire.c:306 acquire_append device is tape bart-sd: acquire.c:310 Dec reserve=0 bart-sd: acquire.c:378 Not in append mode, try mount. bart-sd: acquire.c:384 Do mount_next_write_vol bart-sd: mount.c:51 Enter mount_next_volume(release=0) bart-sd: mount.c:86 Before dir_find_next_appendable_volume. bart-sd: askdir.c:230 dir_find_next_appendable_volume bart-sd: askdir.c:242 >dird: CatReq Job=BaculaCatalog.2005-10-17_09.34.06 FindMedia=1 pool_name=ChangerPool media_type=DLT40 bart-sd: askdir.c:165 <dird 1000 OK VolName=DailySet300 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=3 VolErrors=0 VolWrites=2628536 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 bart-sd: askdir.c:187 do_reqest_vol_info return true slot=0 Volume=DailySet300 bart-sd: askdir.c:258 dir_find_next_appendable_volume return true bart-sd: reserve.c:118 new_volume DailySet300 bart-sd: mount.c:98 After find_next_append. Vol=DailySet300 Slot=0 Parts=0 bart-sd: askdir.c:230 dir_find_next_appendable_volume bart-sd: askdir.c:242 >dird: CatReq Job=BaculaCatalog.2005-10-17_09.34.06 FindMedia=1 pool_name=ChangerPool media_type=DLT40 bart-sd: askdir.c:165 <dird 1000 OK VolName=DailySet300 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=3 VolErrors=0 VolWrites=2628536 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 bart-sd: askdir.c:187 do_reqest_vol_info return true slot=0 Volume=DailySet300 bart-sd: askdir.c:258 dir_find_next_appendable_volume return true bart-sd: reserve.c:118 new_volume DailySet300 bart-sd: autochanger.c:70 Want changer slot=0 bart-sd: mount.c:118 autoload_dev returns 0 bart-sd: mount.c:126 (1)Ask=0bart-sd: mount.c:134 Ask=0 autochanger=0 bart-sd: mount.c:144 want vol=DailySet300 bart-sd: dev.c:269 Close fd for mode change. bart-sd: dev.c:277 open dev: tape=2 dev_name="GoceptChangerDev" (/dev/nst0) vol=DailySet300 mode=OPEN_READ_WRITE bart-sd: dev.c:335 open dev: device is tape bart-sd: autochanger.c:191 Locking changer GoceptChanger bart-sd: bpipe.c:291 Run program returning 0 bart-sd: autochanger.c:162 run_prog: /etc/bacula/mtx-changer /dev/sg3 loaded 0 /dev/nst0 0 stat=0 result=7 bart-sd: autochanger.c:200 Unlocking changer GoceptChanger bart-sd: dev.c:358 Try open "GoceptChangerDev" (/dev/nst0) mode=OPEN_READ_WRITE nonblocking=0 bart-sd: dev.c:397 openmode=2 OPEN_READ_WRITE bart-sd: dev.c:410 open dev: tape 8 opened bart-sd: label.c:71 Enter read_volume_label device="GoceptChangerDev" (/dev/nst0) vol=DailySet300 dev_Vol=DailySet306 bart-sd: dev.c:654 rewind_dev fd=8 "GoceptChangerDev" (/dev/nst0) bart-sd: label.c:138 Big if statement in read_volume_label bart-sd: block.c:879 Full read() in read_block_from_device() len=64512 bart-sd: block.c:943 Read device got 64512 bytes at 0:0 bart-sd: block.c:284 unser_block_header block_len=197 bart-sd: block.c:295 Read binbuf = 173 24 block_len=197 bart-sd: block.c:1065 At end of read block bart-sd: block.c:1078 Exit read_block read_len=64512 block_len=197 bart-sd: label.c:755 unser_vol_label Volume Label: Id : Bacula 1.0 immortal VerNo : 11 VolName : DailySet306 PrevVolName : VolFile : 0 LabelType : VOL_LABEL LabelSize : 161 PoolName : ChangerPool MediaType : DLT40 PoolType : Backup HostName : bart Date label written: 04-Aug-2005 23:21 bart-sd: reserve.c:118 new_volume DailySet306 bart-sd: label.c:206 Compare Vol names: VolName=DailySet300 hdr=DailySet306 bart-sd: label.c:210 Wrong Volume mounted on device "GoceptChangerDev" (/dev/nst0): Wanted DailySet300 have DailySet306 bart-sd: label.c:218 return VOL_NAME_ERROR bart-sd: dev.c:654 rewind_dev fd=8 "GoceptChangerDev" (/dev/nst0) bart-sd: label.c:245 return 4 bart-sd: mount.c:181 Want dirVol=DailySet300 dirStat=Recycle bart-sd: mount.c:203 Vol NAME Error Name=DailySet300 bart-sd: askdir.c:211 >dird: CatReq Job=BaculaCatalog.2005-10-17_09.34.06 GetVolInfo VolName=DailySet306 write=1 bart-sd: askdir.c:165 <dird 1998 Volume "DailySet306" status is Full, but should be Append, Purged or Recycle. bart-sd: askdir.c:177 Bad response from Dir fields=-1: 1998 Volume "DailySet306" status is Full, but should be Append, Purged or Recycle. bart-sd: mount.c:77 mount_next_volume release=1 bart-sd: reserve.c:197 free_volume DailySet306 bart-sd: dev.c:654 rewind_dev fd=8 "GoceptChangerDev" (/dev/nst0) bart-sd: mount.c:474 release_volume bart-sd: mount.c:86 Before dir_find_next_appendable_volume. bart-sd: askdir.c:230 dir_find_next_appendable_volume bart-sd: askdir.c:242 >dird: CatReq Job=BaculaCatalog.2005-10-17_09.34.06 FindMedia=1 pool_name=ChangerPool media_type=DLT40 bart-sd: askdir.c:165 <dird 1000 OK VolName=DailySet300 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=3 VolErrors=0 VolWrites=2628536 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 bart-sd: askdir.c:187 do_reqest_vol_info return true slot=0 Volume=DailySet300 bart-sd: askdir.c:258 dir_find_next_appendable_volume return true bart-sd: reserve.c:118 new_volume DailySet300 bart-sd: mount.c:98 After find_next_append. Vol=DailySet300 Slot=0 Parts=0 bart-sd: askdir.c:230 dir_find_next_appendable_volume bart-sd: askdir.c:242 >dird: CatReq Job=BaculaCatalog.2005-10-17_09.34.06 FindMedia=1 pool_name=ChangerPool media_type=DLT40 bart-sd: askdir.c:165 <dird 1000 OK VolName=DailySet300 VolJobs=0 VolFiles=0 VolBlocks=0 VolBytes=1 VolMounts=3 VolErrors=0 VolWrites=2628536 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Recycle Slot=0 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0 VolWriteTime=0 EndFile=0 EndBlock=0 VolParts=0 LabelType=0 bart-sd: askdir.c:187 do_reqest_vol_info return true slot=0 Volume=DailySet300 bart-sd: askdir.c:258 dir_find_next_appendable_volume return true bart-sd: reserve.c:118 new_volume DailySet300 bart-sd: autochanger.c:70 Want changer slot=0 bart-sd: mount.c:118 autoload_dev returns 0 bart-sd: mount.c:134 Ask=1 autochanger=0 bart-sd: askdir.c:556 enter dir_ask_sysop_to_mount_volume bart-sd: askdir.c:573 Mount "DailySet300" on device ""GoceptChangerDev" (/dev/nst0)" for Job BaculaCatalog.2005-10-17_09.34.06 bart-sd: wait.c:51 Enter blocked=BST_DOING_ACQUIRE bart-sd: wait.c:73 blocked=BST_DOING_ACQUIRE bart-sd: wait.c:86 I'm going to sleep on device "GoceptChangerDev" (/dev/nst0). HB=0 wait=3600
