Incoming call on SIP trunk not going to voicemail

Hi all

I have a SIP trunk setup with my SIP provider (www.vox.co.za). Incoming calls work fine, except when the extention does not answer. Instead of going to voicemail it just hangs up. What I can not understand is, that when another internal extention dials and the extension does not answer, it goes to voicemail.
Below is my audit trail of when it happens:
– Executing [27878021734@from-trunk:1] Set(“SIP/27878021734-08c3d088”, “__FROM_DID=27878021734”) in new stack
– Executing [27878021734@from-trunk:2] Gosub(“SIP/27878021734-08c3d088”, “app-blacklist-check|s|1”) in new stack
– Executing [s@app-blacklist-check:1] LookupBlacklist(“SIP/27878021734-08c3d088”, “”) in new stack
– Executing [s@app-blacklist-check:2] GotoIf(“SIP/27878021734-08c3d088”, “0?blacklisted”) in new stack
– Executing [s@app-blacklist-check:3] Set(“SIP/27878021734-08c3d088”, “CALLED_BLACKLIST=1”) in new stack
– Executing [s@app-blacklist-check:4] Return(“SIP/27878021734-08c3d088”, “”) in new stack
– Executing [27878021734@from-trunk:3] ExecIf(“SIP/27878021734-08c3d088”, “0 |Set|CALLERID(name)=27834571492”) in new stack
– Executing [27878021734@from-trunk:4] Set(“SIP/27878021734-08c3d088”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
– Executing [27878021734@from-trunk:5] SetCallerPres(“SIP/27878021734-08c3d088”, “allowed_not_screened”) in new stack
– Executing [27878021734@from-trunk:6] Goto(“SIP/27878021734-08c3d088”, “ext-group|600|1”) in new stack
– Goto (ext-group,600,1)
– Executing [600@ext-group:1] Macro(“SIP/27878021734-08c3d088”, “user-callerid|”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/27878021734-08c3d088”, “AMPUSER=27834571492”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/27878021734-08c3d088”, “0?report”) in new stack
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/27878021734-08c3d088”, “1|Set|REALCALLERIDNUM=27834571492”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/27878021734-08c3d088”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/27878021734-08c3d088”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/27878021734-08c3d088”, “1?report”) in new stack
– Goto (macro-user-callerid,s,10)
– Executing [s@macro-user-callerid:10] GotoIf(“SIP/27878021734-08c3d088”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:11] Set(“SIP/27878021734-08c3d088”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:12] GotoIf(“SIP/27878021734-08c3d088”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,19)
– Executing [s@macro-user-callerid:19] NoOp(“SIP/27878021734-08c3d088”, “Using CallerID “+27834571492” <27834571492>”) in new stack
– Executing [600@ext-group:2] GotoIf(“SIP/27878021734-08c3d088”, “1?skipdb”) in new stack
– Goto (ext-group,600,4)
– Executing [600@ext-group:4] Set(“SIP/27878021734-08c3d088”, “__NODEST=”) in new stack
– Executing [600@ext-group:5] Set(“SIP/27878021734-08c3d088”, “__BLKVM_OVERRIDE=BLKVM/600/SIP/27878021734-08c3d088”) in new stack
– Executing [600@ext-group:6] Set(“SIP/27878021734-08c3d088”, “__BLKVM_BASE=600”) in new stack
– Executing [600@ext-group:7] Set(“SIP/27878021734-08c3d088”, “DB(BLKVM/600/SIP/27878021734-08c3d088)=TRUE”) in new stack
– Executing [600@ext-group:8] Set(“SIP/27878021734-08c3d088”, “RRNODEST=”) in new stack
– Executing [600@ext-group:9] Set(“SIP/27878021734-08c3d088”, “__NODEST=600”) in new stack
– Executing [600@ext-group:10] Set(“SIP/27878021734-08c3d088”, “RecordMethod=Group”) in new stack
– Executing [600@ext-group:11] Macro(“SIP/27878021734-08c3d088”, “record-enable|1000-1001|Group”) in new stack
– Executing [s@macro-record-enable:1] GotoIf(“SIP/27878021734-08c3d088”, “1?check”) in new stack
– Goto (macro-record-enable,s,4)
– Executing [s@macro-record-enable:4] AGI(“SIP/27878021734-08c3d088”, “recordingcheck|20100224-161554|1267020954.23”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
– AGI Script recordingcheck completed, returning 0
– Executing [s@macro-record-enable:5] MacroExit(“SIP/27878021734-08c3d088”, “”) in new stack
– Executing [600@ext-group:12] Set(“SIP/27878021734-08c3d088”, “RingGroupMethod=ringall”) in new stack
– Executing [600@ext-group:13] Macro(“SIP/27878021734-08c3d088”, “dial|20|tr|1000-1001”) in new stack
– Executing [s@macro-dial:1] GotoIf(“SIP/27878021734-08c3d088”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing [s@macro-dial:3] AGI(“SIP/27878021734-08c3d088”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager_additional.conf’: Found
== Parsing ‘/etc/asterisk/manager_custom.conf’: Found
== Manager ‘admin’ logged on from 127.0.0.1
dialparties.agi: Caller ID name is ‘+27834571492’ number is '27834571492’
dialparties.agi: Methodology of ring is ‘ringall’
– dialparties.agi: Added extension 1000 to extension map
– dialparties.agi: Added extension 1001 to extension map
– dialparties.agi: Extension 1000 cf is disabled
– dialparties.agi: Extension 1001 cf is disabled
– dialparties.agi: Extension 1000 do not disturb is disabled
– dialparties.agi: Extension 1001 do not disturb is disabled
– dialparties.agi: dbset CALLTRACE/1000 to 27834571492
– dialparties.agi: dbset CALLTRACE/1001 to 27834571492
– dialparties.agi: Filtered ARG3: 1000-1001
== Manager ‘admin’ logged off from 127.0.0.1
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:7] Dial(“SIP/27878021734-08c3d088”, “SIP/1000&SIP/1001|20|trM(auto-blkvm)”) in new stack
– Called 1001
– SIP/1001-08c7b9f8 is ringing
– Nobody picked up in 20000 ms
– Executing [s@macro-dial:8] Set(“SIP/27878021734-08c3d088”, “DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-dial:9] GosubIf(“SIP/27878021734-08c3d088”, “0?NOANSWER|1”) in new stack
– Executing [600@ext-group:14] Set(“SIP/27878021734-08c3d088”, “RingGroupMethod=”) in new stack
– Executing [600@ext-group:15] GotoIf(“SIP/27878021734-08c3d088”, “0?nodest”) in new stack
– Executing [600@ext-group:16] Set(“SIP/27878021734-08c3d088”, “__NODEST=”) in new stack
– Executing [600@ext-group:17] DBdel(“SIP/27878021734-08c3d088”, “BLKVM/600/SIP/27878021734-08c3d088”) in new stack
– DBdel: family=BLKVM, key=600/SIP/27878021734-08c3d088
– Executing [600@ext-group:18] Goto(“SIP/27878021734-08c3d088”, “ext-local|vmb1000|1”) in new stack
– Goto (ext-local,vmb1000,1)
– Executing [vmb1000@ext-local:1] Macro(“SIP/27878021734-08c3d088”, “vm|1000|BUSY|”) in new stack
– Executing [s@macro-vm:1] Macro(“SIP/27878021734-08c3d088”, “user-callerid|SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/27878021734-08c3d088”, “AMPUSER=27834571492”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/27878021734-08c3d088”, “0?report”) in new stack
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/27878021734-08c3d088”, “0|Set|REALCALLERIDNUM=27834571492”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/27878021734-08c3d088”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/27878021734-08c3d088”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/27878021734-08c3d088”, “1?report”) in new stack
– Goto (macro-user-callerid,s,10)
– Executing [s@macro-user-callerid:10] GotoIf(“SIP/27878021734-08c3d088”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,19)
– Executing [s@macro-user-callerid:19] NoOp(“SIP/27878021734-08c3d088”, “Using CallerID “+27834571492” <27834571492>”) in new stack
– Executing [s@macro-vm:2] Set(“SIP/27878021734-08c3d088”, “VMGAIN=”"") in new stack
– Executing [s@macro-vm:3] GotoIf(“SIP/27878021734-08c3d088”, “1?vmx|1”) in new stack
– Goto (macro-vm,vmx,1)
– Executing [vmx@macro-vm:1] Set(“SIP/27878021734-08c3d088”, “MEXTEN=1000”) in new stack
– Executing [vmx@macro-vm:2] Set(“SIP/27878021734-08c3d088”, “MMODE=BUSY”) in new stack
– Executing [vmx@macro-vm:3] Set(“SIP/27878021734-08c3d088”, “RETVM=”) in new stack
– Executing [vmx@macro-vm:4] Set(“SIP/27878021734-08c3d088”, “MODE=busy”) in new stack
– Executing [vmx@macro-vm:5] GotoIf(“SIP/27878021734-08c3d088”, “1?chknomsg”) in new stack
– Goto (macro-vm,vmx,7)
– Executing [vmx@macro-vm:7] GotoIf(“SIP/27878021734-08c3d088”, “0?s-BUSY|1”) in new stack
– Executing [vmx@macro-vm:8] GotoIf(“SIP/27878021734-08c3d088”, “1?notdirect”) in new stack
– Goto (macro-vm,vmx,10)
– Executing [vmx@macro-vm:10] NoOp(“SIP/27878021734-08c3d088”, "Checking if ext 1000 is enabled: ") in new stack
– Executing [vmx@macro-vm:11] GotoIf(“SIP/27878021734-08c3d088”, “1?s-BUSY|1”) in new stack
– Goto (macro-vm,s-BUSY,1)
– Executing [s-BUSY@macro-vm:1] NoOp(“SIP/27878021734-08c3d088”, “BUSY voicemail”) in new stack
– Executing [s-BUSY@macro-vm:2] Macro(“SIP/27878021734-08c3d088”, “get-vmcontext|1000”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“SIP/27878021734-08c3d088”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/27878021734-08c3d088”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“SIP/27878021734-08c3d088”, “”) in new stack
– Executing [s-BUSY@macro-vm:3] VoiceMail(“SIP/27878021734-08c3d088”, “1000@default|b”) in new stack
== Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on ‘SIP/27878021734-08c3d088’ in macro ‘vm’
== Spawn extension (ext-local, vmb1000, 1) exited non-zero on ‘SIP/27878021734-08c3d088’

Regards
Morne