>> On Wed, 5 Dec 2007, Martin Simmons wrote:
>>
>>> If that is OK, then I suggest running the SD with debug level 200,
>>> which
>>> might give us a clue where the error occurs.
>>
>> So far I have been unable to get it to fail using -d200, while it does
>> fail if I don't specify a debug level. Maybe there is a timing issue.
>> I'll
>> keep trying.
>>
>> Steve
>
> Strangely, it has also not failed for me at all since I have had debugging
> turned up. I will continue to keep debugging high over the next few days
> and see if it fails at all.
>
> --Marc
>
Okay, finally got the problem to happen again:
---snip---
2-Dec 03:05 escabot-dir JobId 8558: Start Backup JobId 8558,
Job=sun_boot_kim_topaz.2007-12-12_02.00.42
12-Dec 03:05 escabot-dir JobId 8558: Using Device "T50-Drive-1"
12-Dec 03:05 escabot-sd JobId 8558: Error: Autochanger Volume "" not found
in slot 28.
Setting InChanger to zero in catalog.
12-Dec 03:05 escabot-sd JobId 8558: Fatal error: askdir.c:332 NULL Volume
name. This
shouldn't happen!!!
12-Dec 03:05 escabot-sd JobId 8558: Warning: Director wanted Volume
"000067LX".
Current Volume "" not acceptable because:
1998 Volume "" status is , not in Pool.
12-Dec 03:05 escabot-sd JobId 8558: Fatal error: Job 8558 canceled.
12-Dec 03:05 escabot-fd JobId 8558: Fatal error: job.c:1811 Bad response
to Append
Data command. Wanted 3000 OK data
, got 3903 Error append data
---snip---
Then here is what I got in the log with increased sd debugging:
---snip---
escabot-sd: dircmd.c:214-0 <dird: JobId=8558
job=sun_boot_kim_topaz.2007-12-12_02.00.42 job_name=sun_boot_kim_topaz
client_name=escabot-fd type=66 level=68 FileSet=sun_snap-boot_kim_topaz
NoAttr=0 SpoolAttr=0 FileSetMD5=wRNfu9+S35kWu9/dG8+UqA SpoolData=0
WritePartAfterJob=1 PreferMountedVols=0
escabot-sd: dircmd.c:228-0 Do command: JobId=
escabot-sd: job.c:87-0 <dird: JobId=8558
job=sun_boot_kim_topaz.2007-12-12_02.00.42 job_name=sun_boot_kim_topaz
client_name=escabot-fd type=66 level=68 FileSet=sun_snap-boot_kim_topaz
NoAttr=0 SpoolAttr=0 FileSetMD5=wRNfu9+S35kWu9/dG8+UqA SpoolData=0
WritePartAfterJob=1 PreferMountedVols=0
escabot-sd: job.c:141-0 >dird jid=8558: 3000 OK Job SDid=316
SDtime=1196884941 Authorization=GDBD-OLJK-FFFI-GOKH-ALGP-GMGF-JHMN-DENF
escabot-sd: pythonlib.c:237-0 No startup module.
escabot-sd: dircmd.c:214-0 <dird: use storage=SpectraLogicT50
media_type=LTO-3 pool_name=Daily pool_type=Backup append=1 copy=0 stripe=0
escabot-sd: dircmd.c:228-0 Do command: use storage=
escabot-sd: reserve.c:586-0 jid=8558 <dird: use storage=SpectraLogicT50
media_type=LTO-3 pool_name=Daily pool_type=Backup append=1 copy=0 stripe=0
escabot-sd: reserve.c:615-0 jid=8558 <dird device: use device=SpectraLogicT50
escabot-sd: reserve.c:632-0 jid=8558 Storage=SpectraLogicT50
media_type=LTO-3 pool=Daily pool_type=Backup append=1
escabot-sd: reserve.c:634-0 jid=8558 Device=SpectraLogicT50
escabot-sd: reserve.c:683-0 jid=8558 PrefMnt=0 exact=0 suitable=0
chgronly=1 any=0
escabot-sd: reserve.c:828-0 jid=8558 PrefMnt=0 exact=0 suitable=0 chgronly=1
escabot-sd: reserve.c:986-0 jid=8558 search res for SpectraLogicT50
escabot-sd: reserve.c:989-0 jid=8558 Try match changer res=SpectraLogicT50
escabot-sd: reserve.c:995-0 jid=8558 Try changer device T50-Drive-1
escabot-sd: reserve.c:1058-0 jid=8558 chk MediaType device=LTO-3
request=LTO-3
escabot-sd: reserve.c:1081-0 jid=8558 try reserve T50-Drive-1
escabot-sd: reserve.c:1095-0 jid=8558 have_vol=0 vol=
escabot-sd: reserve.c:1254-0 jid=8558 reserve_append device is
"T50-Drive-1" (/dev/nst0)
escabot-sd: reserve.c:1286-0 jid=8558 PrefMnt=0 exact=0 suitable=1
chgronly=1 any=0
escabot-sd: reserve.c:1365-0 jid=8558 OK Res Unused autochanger
"T50-Drive-1" (/dev/nst0).
escabot-sd: reserve.c:1264-0 jid=8558 Inc reserve=1 dev="T50-Drive-1"
(/dev/nst0) 81b0828
escabot-sd: reserve.c:1105-0 jid=8558 Reserved=1 dev_name=SpectraLogicT50
mediatype=LTO-3 pool=Daily ok=1
escabot-sd: askdir.c:256-0 dir_find_next_appendable_volume
escabot-sd: askdir.c:271-0 >dird: CatReq
Job=sun_boot_kim_topaz.2007-12-12_02.00.42 FindMedia=1 pool_name=Daily
media_type=LTO-3
escabot-sd: askdir.c:182-0 <dird 1000 OK VolName=000067LX VolJobs=12
VolFiles=19 VolBlocks=139901 VolBytes=9025357824 VolMounts=11 VolErrors=0
VolWrites=11155326 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append
Slot=28 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0
VolWriteTime=3017012185 EndFile=18 EndBlock=8360 VolParts=0 LabelType=0
MediaId=67
escabot-sd: askdir.c:204-0 do_reqest_vol_info return true slot=28
Volume=000067LX
escabot-sd: reserve.c:406-0 jid=8558 find_vol=000067LX found=1
escabot-sd: reserve.c:181-0 jid=8558 List from find_volume: 000067LX at
81b1eb0 on device "T50-Drive-1" (/dev/nst0)
escabot-sd: reserve.c:538-0 jid=8558 Vol=000067LX on same dev.
escabot-sd: reserve.c:313-0 jid=8558 reserve_volume 000067LX
escabot-sd: reserve.c:181-0 jid=8558 List from begin reserve_volume:
000067LX at 81b1eb0 on device "T50-Drive-1" (/dev/nst0)
escabot-sd: reserve.c:181-0 jid=8558 List from end new volume: 000067LX at
81b1eb0 on device "T50-Drive-1" (/dev/nst0)
escabot-sd: reserve.c:1110-0 jid=8558 looking for Volume=000067LX
escabot-sd: reserve.c:1148-0 jid=8558 >dird changer: 3000 OK use device
device=T50-Drive-1
escabot-sd: reserve.c:1004-0 jid=8558 Device T50-Drive-1 reserved=1 for
append.
escabot-sd: reserve.c:959-0 jid=8558 available device found=SpectraLogicT50
escabot-sd: dircmd.c:214-0 <dird: run
escabot-sd: dircmd.c:228-0 Do command: run
escabot-sd: job.c:156-0 Run_cmd: run
escabot-sd: jcr.c:603-0 OnEntry JobStatus=C set=F
escabot-sd: jcr.c:623-0 OnExit JobStatus=F set=F
escabot-sd: job.c:175-0 sun_boot_kim_topaz.2007-12-12_02.00.42 waiting
1800 sec for FD to contact SD key=GDBD-OLJK-FFFI-GOKH-ALGP-GMGF-JHMN-DENF
escabot-sd: bnet.c:666-0 who=client host=207.74.136.234 port=36643
escabot-sd: dircmd.c:172-0 Conn: Hello Start Job
sun_boot_kim_topaz.2007-12-12_02.00.42
escabot-sd: dircmd.c:177-0 Got a FD connection
escabot-sd: job.c:218-0 Found Job sun_boot_kim_topaz.2007-12-12_02.00.42
escabot-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
escabot-sd: cram-md5.c:133-0 cram-get received: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
escabot-sd: cram-md5.c:152-0 sending resp to challenge:
a+sCgy/GH//2D6RBvFA+VB
escabot-sd: job.c:235-0 OK Authentication jid=8558 Job
sun_boot_kim_topaz.2007-12-12_02.00.42
escabot-sd: job.c:194-0 Running job sun_boot_kim_topaz.2007-12-12_02.00.42
escabot-sd: fd_cmds.c:122-0 Start run
Job=sun_boot_kim_topaz.2007-12-12_02.00.42
escabot-sd: jcr.c:603-0 OnEntry JobStatus=F set=R
escabot-sd: jcr.c:623-0 OnExit JobStatus=R set=R
escabot-sd: fd_cmds.c:160-0 <filed: append open session
escabot-sd: fd_cmds.c:228-0 Append open session: append open session
escabot-sd: fd_cmds.c:238-0 >filed: 3000 OK open ticket = 316
escabot-sd: fd_cmds.c:160-0 <filed: append data 316
escabot-sd: fd_cmds.c:190-0 Append data: append data 316
escabot-sd: fd_cmds.c:192-0 <bfiled: append data 316
escabot-sd: append.c:73-0 Start append data. res=1
escabot-sd: acquire.c:329-0 acquire_append device is tape
escabot-sd: acquire.c:418-0 Not in append mode, try mount.
escabot-sd: acquire.c:424-0 Do mount_next_write_vol
escabot-sd: mount.c:74-0 Enter mount_next_volume(release=0)
dev="T50-Drive-1" (/dev/nst0)
escabot-sd: mount.c:84-0 mount_next_vol retry=0
escabot-sd: mount.c:110-0 Before dir_find_next_appendable_volume.
escabot-sd: askdir.c:256-0 dir_find_next_appendable_volume
escabot-sd: askdir.c:271-0 >dird: CatReq
Job=sun_boot_kim_topaz.2007-12-12_02.00.42 FindMedia=1 pool_name=Daily
media_type=LTO-3
escabot-sd: askdir.c:182-0 <dird 1000 OK VolName=000067LX VolJobs=12
VolFiles=19 VolBlocks=139901 VolBytes=9025357824 VolMounts=11 VolErrors=0
VolWrites=11155326 MaxVolBytes=0 VolCapacityBytes=0 VolStatus=Append
Slot=28 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=0
VolWriteTime=3017012185 EndFile=18 EndBlock=8360 VolParts=0 LabelType=0
MediaId=67
escabot-sd: askdir.c:204-0 do_reqest_vol_info return true slot=28
Volume=000067LX
escabot-sd: reserve.c:406-0 jid=8558 find_vol=000067LX found=1
escabot-sd: reserve.c:181-0 jid=8558 List from find_volume: 000067LX at
81b1eb0 on device "T50-Drive-1" (/dev/nst0)
escabot-sd: reserve.c:538-0 jid=8558 Vol=000067LX on same dev.
escabot-sd: reserve.c:313-0 jid=8558 reserve_volume 000067LX
escabot-sd: reserve.c:181-0 jid=8558 List from begin reserve_volume:
000067LX at 81b1eb0 on device "T50-Drive-1" (/dev/nst0)
escabot-sd: reserve.c:181-0 jid=8558 List from end new volume: 000067LX at
81b1eb0 on device "T50-Drive-1" (/dev/nst0)
escabot-sd: mount.c:122-0 After find_next_append. Vol=000067LX Slot=28
Parts=0
escabot-sd: autochanger.c:217-0 After changer, status=0
escabot-sd: mount.c:142-0 autoload_dev returns 1
escabot-sd: mount.c:150-0 (1)Ask=0
escabot-sd: mount.c:158-0 Ask=0 autochanger=1
escabot-sd: mount.c:168-0 want vol=000067LX
escabot-sd: label.c:81-0 Enter read_volume_label res=1
device="T50-Drive-1" (/dev/nst0) vol=000067LX dev_Vol=*NULL*
escabot-sd: label.c:100-0 return VOL_NAME_ERROR
escabot-sd: label.c:262-0 return 5
escabot-sd: mount.c:237-0 Want dirVol=000067LX dirStat=Append
escabot-sd: mount.c:260-0 Vol NAME Error Name=000067LX
escabot-sd: askdir.c:229-0 >dird: CatReq
Job=sun_boot_kim_topaz.2007-12-12_02.00.42 GetVolInfo VolName= write=1
escabot-sd: askdir.c:182-0 <dird 1998 Volume "" status is , not in Pool.
escabot-sd: askdir.c:194-0 Bad response from Dir fields=-1, len=40: 1998
Volume "" status is , not in Pool.
escabot-sd: askdir.c:229-0 >dird: CatReq
Job=sun_boot_kim_topaz.2007-12-12_02.00.42 GetVolInfo VolName= write=0
escabot-sd: askdir.c:182-0 <dird 1998 Volume "" status is , is not Enabled.
escabot-sd: askdir.c:194-0 Bad response from Dir fields=-1, len=43: 1998
Volume "" status is , is not Enabled.
escabot-sd: jcr.c:603-0 OnEntry JobStatus=R set=f
escabot-sd: jcr.c:623-0 OnExit JobStatus=f set=f
escabot-sd: askdir.c:333 NULL Volume name. This shouldn't happen!!!
escabot-sd: mount.c:84-0 mount_next_vol retry=1
escabot-sd: jcr.c:603-0 OnEntry JobStatus=f set=f
escabot-sd: jcr.c:623-0 OnExit JobStatus=f set=f
escabot-sd: acquire.c:461-0 Dec reserve=0 dev="T50-Drive-1" (/dev/nst0)
escabot-sd: jcr.c:603-0 OnEntry JobStatus=f set=E
escabot-sd: jcr.c:623-0 OnExit JobStatus=f set=E
escabot-sd: jcr.c:603-0 OnEntry JobStatus=f set=E
ot-sd: jcr.c:623-0 OnExit JobStatus=f set=E
ot-sd: jcr.c:603-0 OnEntry JobStatus=f set=T
ot-sd: jcr.c:623-0 OnExit JobStatus=f set=T
ot-sd: pythonlib.c:237-0 No startup module.
ot-sd: dircmd.c:231-0 Command run reqeusts quit
ot-sd: pythonlib.c:237-0 No startup module.
ot-sd: mem_pool.c:377-0 garbage collect memory pool
ot-sd: bnet.c:666-0 who=client host=207.74.136.234 port=36643
ot-sd: dircmd.c:172-0 Conn: Hello Director escabot-dir calling
ot-sd: dircmd.c:185-0 Got a DIR connection
ot-sd: jcr.c:603-0 OnEntry JobStatus=escabot-sd: jcr.c:623-0 OnExit
JobStatus=C set=C
ot-sd: cram-md5.c:73-0 send: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
ot-sd: cram-md5.c:133-0 cram-get received: auth cram-md5
<[EMAIL PROTECTED]> ssl=0
ot-sd: cram-md5.c:152-0 sending resp to challenge: N11st4/56G4xgGIdk/JL0C
ot-sd: dircmd.c:207-0 Message channel init completed.
ot-sd: dircmd.c:214-0 <dird: cancel
Job=sun_boot_kim_topaz.2007-12-12_02.00.42
ot-sd: dircmd.c:228-0 Do command: cancel
ot-sd: pythonlib.c:237-0 No startup module.
ot-sd: mem_pool.c:377-0 garbage collect memory pool
---snip---
--Marc
>
>>
>> -------------------------------------------------------------------------
>> SF.Net email is sponsored by:
>> Check out the new SourceForge.net Marketplace.
>> It's the best place to buy or sell services for
>> just about anything Open Source.
>> http://sourceforge.net/services/buy/index.php
>> _______________________________________________
>> Bacula-users mailing list
>> Bacula-users@lists.sourceforge.net
>> https://lists.sourceforge.net/lists/listinfo/bacula-users
>>
>>
>>
>>
>
>
>
> -------------------------------------------------------------------------
> SF.Net email is sponsored by:
> Check out the new SourceForge.net Marketplace.
> It's the best place to buy or sell services for
> just about anything Open Source.
> http://sourceforge.net/services/buy/index.php
> _______________________________________________
> Bacula-users mailing list
> Bacula-users@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/bacula-users
>
> !DSPAM:1,475adc17206871087411099!
>
>
-------------------------------------------------------------------------
SF.Net email is sponsored by:
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://sourceforge.net/services/buy/index.php
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
