Dial extension goes directly to voicemail

Here is the setup:

I have 3 extensions 100, 200, and 500. The endpoints are in one location and the pbx is hosted at rentpbx.

The phones are registered as shown below:
Name/username Host Dyn Forcerport ACL Port Status
100/100 XX.XXX.XXX.X D N A 1082 OK (82 ms)
200/200 XX.XXX.XXX.X D N A 1083 OK (83 ms)
500/500 XX.XXX.XXX.X D N A 5062 OK (76 ms)

The hints for these extensions are shown below:
core show hint 100, 200, and 500
100@ext-local : SIP/100&Custom:DND10 State:Idle Watchers 2
200@ext-local : SIP/200&Custom:DND20 State:Idle Watchers 2
500@ext-local : SIP/500&Custom:DND50 State:Idle Watchers 2

I can dial 500 from both 100 and 200 and the phone rings. When I dial 100 and 200 from any other phone it goes directly to voice mail with a message “The person at extension xxx is unavailable…”

Neither 100 or 200 have DND set on. There are no follow me, forwarding, etc. The console shows the following when I dial for example 100:

= Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
== Extension Changed 500[ext-local] new state InUse for Notify User 200
== Extension Changed 500[ext-local] new state InUse for Notify User 100
– Executing [100@from-internal:1] Set(“SIP/500-00000006”, “__RINGTIMER=15”) in new stack
– Executing [100@from-internal:2] Macro(“SIP/500-00000006”, “exten-vm,100,100,0,0,0”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“SIP/500-00000006”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/500-00000006”, “AMPUSER=500”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/500-00000006”, “0?report”) in new stack
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/500-00000006”, “1?Set(REALCALLERIDNUM=500)”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/500-00000006”, “AMPUSER=500”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/500-00000006”, “AMPUSERCIDNAME=Tara Richards”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/500-00000006”, “0?report”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/500-00000006”, “AMPUSERCID=500”) in new stack
– Executing [s@macro-user-callerid:8] Set(“SIP/500-00000006”, “CALLERID(all)=“Tara Richards” <500>”) in new stack
– Executing [s@macro-user-callerid:9] GotoIf(“SIP/500-00000006”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:10] ExecIf(“SIP/500-00000006”, “0?Set(GROUP(concurrency_limit)=500)”) in new stack
– Executing [s@macro-user-callerid:11] ExecIf(“SIP/500-00000006”, “0?Set(CHANNEL(language)=)”) in new stack
– Executing [s@macro-user-callerid:12] GosubIf(“SIP/500-00000006”, “7?sub-ccss,s,1(macro-exten-vm,100)”) in new stack
– Executing [s@sub-ccss:1] ExecIf(“SIP/500-00000006”, “0?Return()”) in new stack
– Executing [s@sub-ccss:2] Set(“SIP/500-00000006”, “CCSS_SETUP=TRUE”) in new stack
– Executing [s@sub-ccss:3] GosubIf(“SIP/500-00000006”, “0?monitor_config,1(macro-exten-vm,100):monitor_default,1(macro-exten-vm,100)”) in new stack
– Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/500-00000006”, “1?is_exten”) in new stack
– Goto (sub-ccss,monitor_default,4)
– Executing [monitor_default@sub-ccss:4] Set(“SIP/500-00000006”, “CALLCOMPLETION(cc_monitor_policy)=generic”) in new stack
– Executing [monitor_default@sub-ccss:5] Set(“SIP/500-00000006”, “CALLCOMPLETION(cc_max_monitors)=5”) in new stack
– Executing [monitor_default@sub-ccss:6] Return(“SIP/500-00000006”, “TRUE”) in new stack
– Executing [s@sub-ccss:4] GosubIf(“SIP/500-00000006”, “7?agent_config,1():agent_default,1()”) in new stack
– Executing [agent_config@sub-ccss:1] Set(“SIP/500-00000006”, “CALLCOMPLETION(cc_agent_policy)=generic”) in new stack
– Executing [agent_config@sub-ccss:2] Set(“SIP/500-00000006”, “CALLCOMPLETION(cc_offer_timer)=30”) in new stack
– Executing [agent_config@sub-ccss:3] Set(“SIP/500-00000006”, “CALLCOMPLETION(ccbs_available_timer)=”) in new stack
– Executing [agent_config@sub-ccss:4] Set(“SIP/500-00000006”, “CALLCOMPLETION(ccnr_available_timer)=”) in new stack
– Executing [agent_config@sub-ccss:5] Set(“SIP/500-00000006”, “CALLCOMPLETION(cc_callback_macro)=ccss-default”) in new stack
– Executing [agent_config@sub-ccss:6] ExecIf(“SIP/500-00000006”, “1?Set(CALLCOMPLETION(cc_recall_timer)=)”) in new stack
– Executing [agent_config@sub-ccss:7] ExecIf(“SIP/500-00000006”, “1?Set(CALLCOMPLETION(cc_max_agents)=)”) in new stack
– Executing [agent_config@sub-ccss:8] ExecIf(“SIP/500-00000006”, “0?Set(CALLCOMPLETION(cc_agent_dialstring)=Local/500_100@from-ccss-)”) in new stack
– Executing [agent_config@sub-ccss:9] Set(“SIP/500-00000006”, “CALLCOMPLETION(cc_callback_macro)=ccss-default”) in new stack
– Executing [agent_config@sub-ccss:10] Return(“SIP/500-00000006”, “”) in new stack
– Executing [s@sub-ccss:5] Set(“SIP/500-00000006”, “DB(AMPUSER/500/ccss/last_number)=100”) in new stack
– Executing [s@sub-ccss:6] Return(“SIP/500-00000006”, “”) in new stack
– Executing [s@macro-user-callerid:13] GotoIf(“SIP/500-00000006”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:14] Set(“SIP/500-00000006”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:15] GotoIf(“SIP/500-00000006”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,26)
– Executing [s@macro-user-callerid:26] Set(“SIP/500-00000006”, “CALLERID(number)=500”) in new stack
– Executing [s@macro-user-callerid:27] Set(“SIP/500-00000006”, “CALLERID(name)=Tara Richards”) in new stack
– Executing [s@macro-user-callerid:28] Set(“SIP/500-00000006”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-exten-vm:2] Set(“SIP/500-00000006”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“SIP/500-00000006”, “__EXTTOCALL=100”) in new stack
– Executing [s@macro-exten-vm:4] Set(“SIP/500-00000006”, “__PICKUPMARK=100”) in new stack
– Executing [s@macro-exten-vm:5] Set(“SIP/500-00000006”, “RT=15”) in new stack
– Executing [s@macro-exten-vm:6] Gosub(“SIP/500-00000006”, “sub-record-check,s,1(exten,100,)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/500-00000006”, “1?check”) in new stack
– Goto (sub-record-check,s,6)
– Executing [s@sub-record-check:6] Set(“SIP/500-00000006”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:7] GotoIf(“SIP/500-00000006”, “1?next”) in new stack
– Goto (sub-record-check,s,10)
– Executing [s@sub-record-check:10] ExecIf(“SIP/500-00000006”, “0?Return()”) in new stack
– Executing [s@sub-record-check:11] GotoIf(“SIP/500-00000006”, “0?exten,1”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/500-00000006”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/500-00000006”, “0?Set(__REC_POLICY_MODE=)”) in new stack
– Executing [s@sub-record-check:14] Set(“SIP/500-00000006”, “NOW=1447411368”) in new stack
– Executing [s@sub-record-check:15] Set(“SIP/500-00000006”, “__DAY=13”) in new stack
– Executing [s@sub-record-check:16] Set(“SIP/500-00000006”, “__MONTH=11”) in new stack
– Executing [s@sub-record-check:17] Set(“SIP/500-00000006”, “__YEAR=2015”) in new stack
– Executing [s@sub-record-check:18] Set(“SIP/500-00000006”, “__TIMESTR=20151113-054248”) in new stack
– Executing [s@sub-record-check:19] Set(“SIP/500-00000006”, “__FROMEXTEN=500”) in new stack
– Executing [s@sub-record-check:20] Set(“SIP/500-00000006”, “__CALLFILENAME=exten-100-500-20151113-054248-1447411367.6”) in new stack
– Executing [s@sub-record-check:21] Goto(“SIP/500-00000006”, “exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] GotoIf(“SIP/500-00000006”, “0?callee”) in new stack
– Executing [exten@sub-record-check:2] Set(“SIP/500-00000006”, “__REC_POLICY_MODE=dontcare”) in new stack
– Executing [exten@sub-record-check:3] GotoIf(“SIP/500-00000006”, “1?caller”) in new stack
– Goto (sub-record-check,exten,10)
– Executing [exten@sub-record-check:10] Set(“SIP/500-00000006”, “__REC_POLICY_MODE=dontcare”) in new stack
– Executing [exten@sub-record-check:11] GosubIf(“SIP/500-00000006”, “0?record,1(exten,100,500)”) in new stack
– Executing [exten@sub-record-check:12] Return(“SIP/500-00000006”, “”) in new stack
– Executing [s@macro-exten-vm:7] Macro(“SIP/500-00000006”, “dial-one,15,tr,100”) in new stack
– Executing [s@macro-dial-one:1] Set(“SIP/500-00000006”, “DEXTEN=100”) in new stack
– Executing [s@macro-dial-one:2] Set(“SIP/500-00000006”, “DIALSTATUS_CW=”) in new stack
– Executing [s@macro-dial-one:3] GosubIf(“SIP/500-00000006”, “0?screen,1()”) in new stack
– Executing [s@macro-dial-one:4] GosubIf(“SIP/500-00000006”, “0?cf,1()”) in new stack
– Executing [s@macro-dial-one:5] GotoIf(“SIP/500-00000006”, “1?skip1”) in new stack
– Goto (macro-dial-one,s,8)
– Executing [s@macro-dial-one:8] GotoIf(“SIP/500-00000006”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:9] GotoIf(“SIP/500-00000006”, “0?continue”) in new stack
– Executing [s@macro-dial-one:10] Set(“SIP/500-00000006”, “EXTHASCW=ENABLED”) in new stack
– Executing [s@macro-dial-one:11] GotoIf(“SIP/500-00000006”, “0?next1:cwinusebusy”) in new stack
– Goto (macro-dial-one,s,23)
– Executing [s@macro-dial-one:23] GotoIf(“SIP/500-00000006”, “1?next3:continue”) in new stack
– Goto (macro-dial-one,s,24)
– Executing [s@macro-dial-one:24] ExecIf(“SIP/500-00000006”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
– Executing [s@macro-dial-one:25] GotoIf(“SIP/500-00000006”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:26] GosubIf(“SIP/500-00000006”, “1?dstring,1():dlocal,1()”) in new stack
– Executing [dstring@macro-dial-one:1] Set(“SIP/500-00000006”, “DSTRING=”) in new stack
– Executing [dstring@macro-dial-one:2] Set(“SIP/500-00000006”, “DEVICES=100”) in new stack
– Executing [dstring@macro-dial-one:3] ExecIf(“SIP/500-00000006”, “0?Return()”) in new stack
– Executing [dstring@macro-dial-one:4] ExecIf(“SIP/500-00000006”, “0?Set(DEVICES=00)”) in new stack
– Executing [dstring@macro-dial-one:5] Set(“SIP/500-00000006”, “LOOPCNT=1”) in new stack
– Executing [dstring@macro-dial-one:6] Set(“SIP/500-00000006”, “ITER=1”) in new stack
– Executing [dstring@macro-dial-one:7] Set(“SIP/500-00000006”, “THISDIAL=SIP/100”) in new stack
– Executing [dstring@macro-dial-one:8] GosubIf(“SIP/500-00000006”, “1?zap2dahdi,1()”) in new stack
– Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/500-00000006”, “0?Return()”) in new stack
– Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/500-00000006”, “NEWDIAL=”) in new stack
– Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/500-00000006”, “LOOPCNT2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/500-00000006”, “ITER2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/500-00000006”, “THISPART2=SIP/100”) in new stack
– Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/500-00000006”, “0?Set(THISPART2=DAHDI/100)”) in new stack
– Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/500-00000006”, “NEWDIAL=SIP/100&”) in new stack
– Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/500-00000006”, “ITER2=2”) in new stack
– Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/500-00000006”, “0?begin2”) in new stack
– Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/500-00000006”, “THISDIAL=SIP/100”) in new stack
– Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/500-00000006”, “”) in new stack
– Executing [dstring@macro-dial-one:9] Set(“SIP/500-00000006”, “DSTRING=SIP/100&”) in new stack
– Executing [dstring@macro-dial-one:10] Set(“SIP/500-00000006”, “ITER=2”) in new stack
– Executing [dstring@macro-dial-one:11] GotoIf(“SIP/500-00000006”, “0?begin”) in new stack
– Executing [dstring@macro-dial-one:12] Set(“SIP/500-00000006”, “DSTRING=SIP/100”) in new stack
– Executing [dstring@macro-dial-one:13] Return(“SIP/500-00000006”, “”) in new stack
– Executing [s@macro-dial-one:27] GotoIf(“SIP/500-00000006”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:28] GotoIf(“SIP/500-00000006”, “0?skiptrace”) in new stack
– Executing [s@macro-dial-one:29] GosubIf(“SIP/500-00000006”, “1?ctset,1():ctclear,1()”) in new stack
– Executing [ctset@macro-dial-one:1] Set(“SIP/500-00000006”, “DB(CALLTRACE/100)=500”) in new stack
– Executing [ctset@macro-dial-one:2] Return(“SIP/500-00000006”, “”) in new stack
– Executing [s@macro-dial-one:30] Set(“SIP/500-00000006”, “D_OPTIONS=tr”) in new stack
– Executing [s@macro-dial-one:31] ExecIf(“SIP/500-00000006”, “0?SIPAddHeader(Alert-Info: )”) in new stack
– Executing [s@macro-dial-one:32] ExecIf(“SIP/500-00000006”, “0?SIPAddHeader()”) in new stack
– Executing [s@macro-dial-one:33] ExecIf(“SIP/500-00000006”, “0?Set(CHANNEL(musicclass)=)”) in new stack
– Executing [s@macro-dial-one:34] GosubIf(“SIP/500-00000006”, “0?qwait,1()”) in new stack
– Executing [s@macro-dial-one:35] Set(“SIP/500-00000006”, “__CWIGNORE=”) in new stack
– Executing [s@macro-dial-one:36] Set(“SIP/500-00000006”, “__KEEPCID=TRUE”) in new stack
– Executing [s@macro-dial-one:37] GotoIf(“SIP/500-00000006”, “0?usegoto,1”) in new stack
– Executing [s@macro-dial-one:38] GotoIf(“SIP/500-00000006”, “0?godial”) in new stack
– Executing [s@macro-dial-one:39] Set(“SIP/500-00000006”, “CONNECTEDLINE(name,i)=Barbara Brewster”) in new stack
– Executing [s@macro-dial-one:40] Set(“SIP/500-00000006”, “CONNECTEDLINE(num)=100”) in new stack
– Executing [s@macro-dial-one:41] Set(“SIP/500-00000006”, “D_OPTIONS=trI”) in new stack
– Executing [s@macro-dial-one:42] Dial(“SIP/500-00000006”, “SIP/100,15,trI”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Called SIP/100
== Extension Changed 100[ext-local] new state Ringing for Notify User 500
– Connected line update to SIP/500-00000006 prevented.
== Extension Changed 100[ext-local] new state Ringing for Notify User 200
== Extension Changed 100[ext-local] new state Idle for Notify User 500
== Extension Changed 100[ext-local] new state Idle for Notify User 200
== Everyone is busy/congested at this time (1:0/0/1)
– Executing [s@macro-dial-one:43] ExecIf(“SIP/500-00000006”, “0?Set(DIALSTATUS=)”) in new stack
– Executing [s@macro-dial-one:44] GosubIf(“SIP/500-00000006”, “0?s-CHANUNAVAIL,1()”) in new stack
– Executing [s@macro-dial-one:45] MacroExit(“SIP/500-00000006”, “”) in new stack
– Executing [s@macro-exten-vm:8] Set(“SIP/500-00000006”, “SV_DIALSTATUS=CHANUNAVAIL”) in new stack
– Executing [s@macro-exten-vm:9] GosubIf(“SIP/500-00000006”, “0?docfu,1()”) in new stack
– Executing [s@macro-exten-vm:10] GosubIf(“SIP/500-00000006”, “0?docfb,1()”) in new stack
– Executing [s@macro-exten-vm:11] Set(“SIP/500-00000006”, “DIALSTATUS=CHANUNAVAIL”) in new stack
– Executing [s@macro-exten-vm:12] ExecIf(“SIP/500-00000006”, “0?MacroExit()”) in new stack
– Executing [s@macro-exten-vm:13] GotoIf(“SIP/500-00000006”, “0?s-CHANUNAVAIL,1”) in new stack
– Executing [s@macro-exten-vm:14] Macro(“SIP/500-00000006”, “vm,100,CHANUNAVAIL,”) in new stack
– Executing [s@macro-vm:1] Macro(“SIP/500-00000006”, “user-callerid,SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/500-00000006”, “AMPUSER=500”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/500-00000006”, “13?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] GotoIf(“SIP/500-00000006”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,26)
– Executing [s@macro-user-callerid:26] Set(“SIP/500-00000006”, “CALLERID(number)=500”) in new stack
– Executing [s@macro-user-callerid:27] Set(“SIP/500-00000006”, “CALLERID(name)=Tara Richards”) in new stack
– Executing [s@macro-user-callerid:28] Set(“SIP/500-00000006”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-vm:2] Set(“SIP/500-00000006”, “VMGAIN=”"") in new stack
– Executing [s@macro-vm:3] Macro(“SIP/500-00000006”, “blkvm-check,”) in new stack
– Executing [s@macro-blkvm-check:1] Set(“SIP/500-00000006”, “GOSUB_RETVAL=”) in new stack
– Executing [s@macro-blkvm-check:2] ExecIf(“SIP/500-00000006”, “0?Set(GOSUB_RETVAL=TRUE)”) in new stack
– Executing [s@macro-blkvm-check:3] MacroExit(“SIP/500-00000006”, “”) in new stack
– Executing [s@macro-vm:4] GotoIf(“SIP/500-00000006”, “1?vmx,1”) in new stack
– Goto (macro-vm,vmx,1)
– Executing [vmx@macro-vm:1] Set(“SIP/500-00000006”, “MEXTEN=100”) in new stack
– Executing [vmx@macro-vm:2] Set(“SIP/500-00000006”, “MMODE=CHANUNAVAIL”) in new stack
– Executing [vmx@macro-vm:3] Set(“SIP/500-00000006”, “RETVM=”) in new stack
– Executing [vmx@macro-vm:4] Set(“SIP/500-00000006”, “MODE=unavail”) in new stack
– Executing [vmx@macro-vm:5] GotoIf(“SIP/500-00000006”, “1?chknomsg”) in new stack
– Goto (macro-vm,vmx,8)
– Executing [vmx@macro-vm:8] GotoIf(“SIP/500-00000006”, “0?s-CHANUNAVAIL,1”) in new stack
– Executing [vmx@macro-vm:9] GotoIf(“SIP/500-00000006”, “1?notdirect”) in new stack
– Goto (macro-vm,vmx,11)
– Executing [vmx@macro-vm:11] NoOp(“SIP/500-00000006”, “Checking if ext 100 is enabled: disabled”) in new stack
– Executing [vmx@macro-vm:12] GotoIf(“SIP/500-00000006”, “1?s-CHANUNAVAIL,1”) in new stack
– Goto (macro-vm,s-CHANUNAVAIL,1)
– Executing [s-CHANUNAVAIL@macro-vm:1] Macro(“SIP/500-00000006”, “get-vmcontext,100”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“SIP/500-00000006”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/500-00000006”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“SIP/500-00000006”, “”) in new stack
– Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail(“SIP/500-00000006”, “100@default,u”"") in new stack
– <SIP/500-00000006> Playing ‘vm-theperson.gsm’ (language ‘en’)
== Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/500-00000006’ in macro ‘vm’
== Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/500-00000006’ in macro ‘exten-vm’
== Spawn extension (from-internal, 100, 2) exited non-zero on ‘SIP/500-00000006’
– Executing [h@from-internal:1] Hangup(“SIP/500-00000006”, “”) in new stack
== Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/500-00000006’
== Extension Changed 500[ext-local] new state Idle for Notify User 200
== Extension Changed 500[ext-local] new state Idle for Notify User 100

I can ring 500 fine.

Any ideas would be helpful.

Hi,

Set the sendrpid=pai in your extensions.

Thank you,

Daniel Friedman
Trixton LTD.

Okay I made the change via the gui to Send Remote-Party-ID on extension 100 and 500 and this is the console output of a call from x500 to x100:

== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
== Extension Changed 500[ext-local] new state InUse for Notify User 100
== Extension Changed 500[ext-local] new state InUse for Notify User 400
== Extension Changed 500[ext-local] new state InUse for Notify User 600
– Executing [100@from-internal:1] Set(“SIP/500-0000001d”, “__RINGTIMER=15”) in new stack
– Executing [100@from-internal:2] Macro(“SIP/500-0000001d”, “exten-vm,100,100,0,0,0”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“SIP/500-0000001d”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/500-0000001d”, “AMPUSER=500”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/500-0000001d”, “0?report”) in new stack
– Executing [s@macro-user-callerid:3] ExecIf(“SIP/500-0000001d”, “1?Set(REALCALLERIDNUM=500)”) in new stack
– Executing [s@macro-user-callerid:4] Set(“SIP/500-0000001d”, “AMPUSER=500”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/500-0000001d”, “AMPUSERCIDNAME=Tara Richards”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/500-0000001d”, “0?report”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/500-0000001d”, “AMPUSERCID=500”) in new stack
– Executing [s@macro-user-callerid:8] Set(“SIP/500-0000001d”, “CALLERID(all)=“Tara Richards” <500>”) in new stack
– Executing [s@macro-user-callerid:9] GotoIf(“SIP/500-0000001d”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:10] ExecIf(“SIP/500-0000001d”, “0?Set(GROUP(concurrency_limit)=500)”) in new stack
– Executing [s@macro-user-callerid:11] ExecIf(“SIP/500-0000001d”, “0?Set(CHANNEL(language)=)”) in new stack
– Executing [s@macro-user-callerid:12] GosubIf(“SIP/500-0000001d”, “7?sub-ccss,s,1(macro-exten-vm,100)”) in new stack
– Executing [s@sub-ccss:1] ExecIf(“SIP/500-0000001d”, “0?Return()”) in new stack
– Executing [s@sub-ccss:2] Set(“SIP/500-0000001d”, “CCSS_SETUP=TRUE”) in new stack
– Executing [s@sub-ccss:3] GosubIf(“SIP/500-0000001d”, “0?monitor_config,1(macro-exten-vm,100):monitor_default,1(macro-exten-vm,100)”) in new stack
– Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/500-0000001d”, “1?is_exten”) in new stack
– Goto (sub-ccss,monitor_default,4)
– Executing [monitor_default@sub-ccss:4] Set(“SIP/500-0000001d”, “CALLCOMPLETION(cc_monitor_policy)=generic”) in new stack
– Executing [monitor_default@sub-ccss:5] Set(“SIP/500-0000001d”, “CALLCOMPLETION(cc_max_monitors)=5”) in new stack
– Executing [monitor_default@sub-ccss:6] Return(“SIP/500-0000001d”, “TRUE”) in new stack
– Executing [s@sub-ccss:4] GosubIf(“SIP/500-0000001d”, “7?agent_config,1():agent_default,1()”) in new stack
– Executing [agent_config@sub-ccss:1] Set(“SIP/500-0000001d”, “CALLCOMPLETION(cc_agent_policy)=generic”) in new stack
– Executing [agent_config@sub-ccss:2] Set(“SIP/500-0000001d”, “CALLCOMPLETION(cc_offer_timer)=30”) in new stack
– Executing [agent_config@sub-ccss:3] Set(“SIP/500-0000001d”, “CALLCOMPLETION(ccbs_available_timer)=”) in new stack
– Executing [agent_config@sub-ccss:4] Set(“SIP/500-0000001d”, “CALLCOMPLETION(ccnr_available_timer)=”) in new stack
– Executing [agent_config@sub-ccss:5] Set(“SIP/500-0000001d”, “CALLCOMPLETION(cc_callback_macro)=ccss-default”) in new stack
– Executing [agent_config@sub-ccss:6] ExecIf(“SIP/500-0000001d”, “1?Set(CALLCOMPLETION(cc_recall_timer)=)”) in new stack
– Executing [agent_config@sub-ccss:7] ExecIf(“SIP/500-0000001d”, “1?Set(CALLCOMPLETION(cc_max_agents)=)”) in new stack
– Executing [agent_config@sub-ccss:8] ExecIf(“SIP/500-0000001d”, “0?Set(CALLCOMPLETION(cc_agent_dialstring)=Local/500_100@from-ccss-)”) in new stack
– Executing [agent_config@sub-ccss:9] Set(“SIP/500-0000001d”, “CALLCOMPLETION(cc_callback_macro)=ccss-default”) in new stack
– Executing [agent_config@sub-ccss:10] Return(“SIP/500-0000001d”, “”) in new stack
– Executing [s@sub-ccss:5] Set(“SIP/500-0000001d”, “DB(AMPUSER/500/ccss/last_number)=100”) in new stack
– Executing [s@sub-ccss:6] Return(“SIP/500-0000001d”, “”) in new stack
– Executing [s@macro-user-callerid:13] GotoIf(“SIP/500-0000001d”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:14] Set(“SIP/500-0000001d”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:15] GotoIf(“SIP/500-0000001d”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,26)
– Executing [s@macro-user-callerid:26] Set(“SIP/500-0000001d”, “CALLERID(number)=500”) in new stack
– Executing [s@macro-user-callerid:27] Set(“SIP/500-0000001d”, “CALLERID(name)=Tara Richards”) in new stack
– Executing [s@macro-user-callerid:28] Set(“SIP/500-0000001d”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-exten-vm:2] Set(“SIP/500-0000001d”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“SIP/500-0000001d”, “__EXTTOCALL=100”) in new stack
– Executing [s@macro-exten-vm:4] Set(“SIP/500-0000001d”, “__PICKUPMARK=100”) in new stack
– Executing [s@macro-exten-vm:5] Set(“SIP/500-0000001d”, “RT=15”) in new stack
– Executing [s@macro-exten-vm:6] Gosub(“SIP/500-0000001d”, “sub-record-check,s,1(exten,100,)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/500-0000001d”, “1?check”) in new stack
– Goto (sub-record-check,s,6)
– Executing [s@sub-record-check:6] Set(“SIP/500-0000001d”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:7] GotoIf(“SIP/500-0000001d”, “1?next”) in new stack
– Goto (sub-record-check,s,10)
– Executing [s@sub-record-check:10] ExecIf(“SIP/500-0000001d”, “0?Return()”) in new stack
– Executing [s@sub-record-check:11] GotoIf(“SIP/500-0000001d”, “0?exten,1”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/500-0000001d”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/500-0000001d”, “0?Set(__REC_POLICY_MODE=)”) in new stack
– Executing [s@sub-record-check:14] Set(“SIP/500-0000001d”, “NOW=1447431262”) in new stack
– Executing [s@sub-record-check:15] Set(“SIP/500-0000001d”, “__DAY=13”) in new stack
– Executing [s@sub-record-check:16] Set(“SIP/500-0000001d”, “__MONTH=11”) in new stack
– Executing [s@sub-record-check:17] Set(“SIP/500-0000001d”, “__YEAR=2015”) in new stack
– Executing [s@sub-record-check:18] Set(“SIP/500-0000001d”, “__TIMESTR=20151113-111422”) in new stack
– Executing [s@sub-record-check:19] Set(“SIP/500-0000001d”, “__FROMEXTEN=500”) in new stack
– Executing [s@sub-record-check:20] Set(“SIP/500-0000001d”, “__CALLFILENAME=exten-100-500-20151113-111422-1447431262.29”) in new stack
– Executing [s@sub-record-check:21] Goto(“SIP/500-0000001d”, “exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] GotoIf(“SIP/500-0000001d”, “0?callee”) in new stack
– Executing [exten@sub-record-check:2] Set(“SIP/500-0000001d”, “__REC_POLICY_MODE=dontcare”) in new stack
– Executing [exten@sub-record-check:3] GotoIf(“SIP/500-0000001d”, “1?caller”) in new stack
– Goto (sub-record-check,exten,10)
– Executing [exten@sub-record-check:10] Set(“SIP/500-0000001d”, “__REC_POLICY_MODE=dontcare”) in new stack
– Executing [exten@sub-record-check:11] GosubIf(“SIP/500-0000001d”, “0?record,1(exten,100,500)”) in new stack
– Executing [exten@sub-record-check:12] Return(“SIP/500-0000001d”, “”) in new stack
– Executing [s@macro-exten-vm:7] Macro(“SIP/500-0000001d”, “dial-one,15,tr,100”) in new stack
– Executing [s@macro-dial-one:1] Set(“SIP/500-0000001d”, “DEXTEN=100”) in new stack
– Executing [s@macro-dial-one:2] Set(“SIP/500-0000001d”, “DIALSTATUS_CW=”) in new stack
– Executing [s@macro-dial-one:3] GosubIf(“SIP/500-0000001d”, “0?screen,1()”) in new stack
– Executing [s@macro-dial-one:4] GosubIf(“SIP/500-0000001d”, “0?cf,1()”) in new stack
– Executing [s@macro-dial-one:5] GotoIf(“SIP/500-0000001d”, “1?skip1”) in new stack
– Goto (macro-dial-one,s,8)
– Executing [s@macro-dial-one:8] GotoIf(“SIP/500-0000001d”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:9] GotoIf(“SIP/500-0000001d”, “0?continue”) in new stack
– Executing [s@macro-dial-one:10] Set(“SIP/500-0000001d”, “EXTHASCW=ENABLED”) in new stack
– Executing [s@macro-dial-one:11] GotoIf(“SIP/500-0000001d”, “0?next1:cwinusebusy”) in new stack
– Goto (macro-dial-one,s,23)
– Executing [s@macro-dial-one:23] GotoIf(“SIP/500-0000001d”, “1?next3:continue”) in new stack
– Goto (macro-dial-one,s,24)
– Executing [s@macro-dial-one:24] ExecIf(“SIP/500-0000001d”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
– Executing [s@macro-dial-one:25] GotoIf(“SIP/500-0000001d”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:26] GosubIf(“SIP/500-0000001d”, “1?dstring,1():dlocal,1()”) in new stack
– Executing [dstring@macro-dial-one:1] Set(“SIP/500-0000001d”, “DSTRING=”) in new stack
– Executing [dstring@macro-dial-one:2] Set(“SIP/500-0000001d”, “DEVICES=100”) in new stack
– Executing [dstring@macro-dial-one:3] ExecIf(“SIP/500-0000001d”, “0?Return()”) in new stack
– Executing [dstring@macro-dial-one:4] ExecIf(“SIP/500-0000001d”, “0?Set(DEVICES=00)”) in new stack
– Executing [dstring@macro-dial-one:5] Set(“SIP/500-0000001d”, “LOOPCNT=1”) in new stack
– Executing [dstring@macro-dial-one:6] Set(“SIP/500-0000001d”, “ITER=1”) in new stack
– Executing [dstring@macro-dial-one:7] Set(“SIP/500-0000001d”, “THISDIAL=SIP/100”) in new stack
– Executing [dstring@macro-dial-one:8] GosubIf(“SIP/500-0000001d”, “1?zap2dahdi,1()”) in new stack
– Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/500-0000001d”, “0?Return()”) in new stack
– Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/500-0000001d”, “NEWDIAL=”) in new stack
– Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/500-0000001d”, “LOOPCNT2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/500-0000001d”, “ITER2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/500-0000001d”, “THISPART2=SIP/100”) in new stack
– Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/500-0000001d”, “0?Set(THISPART2=DAHDI/100)”) in new stack
– Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/500-0000001d”, “NEWDIAL=SIP/100&”) in new stack
– Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/500-0000001d”, “ITER2=2”) in new stack
– Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/500-0000001d”, “0?begin2”) in new stack
– Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/500-0000001d”, “THISDIAL=SIP/100”) in new stack
– Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/500-0000001d”, “”) in new stack
– Executing [dstring@macro-dial-one:9] Set(“SIP/500-0000001d”, “DSTRING=SIP/100&”) in new stack
– Executing [dstring@macro-dial-one:10] Set(“SIP/500-0000001d”, “ITER=2”) in new stack
– Executing [dstring@macro-dial-one:11] GotoIf(“SIP/500-0000001d”, “0?begin”) in new stack
– Executing [dstring@macro-dial-one:12] Set(“SIP/500-0000001d”, “DSTRING=SIP/100”) in new stack
– Executing [dstring@macro-dial-one:13] Return(“SIP/500-0000001d”, “”) in new stack
– Executing [s@macro-dial-one:27] GotoIf(“SIP/500-0000001d”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:28] GotoIf(“SIP/500-0000001d”, “0?skiptrace”) in new stack
– Executing [s@macro-dial-one:29] GosubIf(“SIP/500-0000001d”, “1?ctset,1():ctclear,1()”) in new stack
– Executing [ctset@macro-dial-one:1] Set(“SIP/500-0000001d”, “DB(CALLTRACE/100)=500”) in new stack
– Executing [ctset@macro-dial-one:2] Return(“SIP/500-0000001d”, “”) in new stack
– Executing [s@macro-dial-one:30] Set(“SIP/500-0000001d”, “D_OPTIONS=tr”) in new stack
– Executing [s@macro-dial-one:31] ExecIf(“SIP/500-0000001d”, “0?SIPAddHeader(Alert-Info: )”) in new stack
– Executing [s@macro-dial-one:32] ExecIf(“SIP/500-0000001d”, “0?SIPAddHeader()”) in new stack
– Executing [s@macro-dial-one:33] ExecIf(“SIP/500-0000001d”, “0?Set(CHANNEL(musicclass)=)”) in new stack
– Executing [s@macro-dial-one:34] GosubIf(“SIP/500-0000001d”, “0?qwait,1()”) in new stack
– Executing [s@macro-dial-one:35] Set(“SIP/500-0000001d”, “__CWIGNORE=”) in new stack
– Executing [s@macro-dial-one:36] Set(“SIP/500-0000001d”, “__KEEPCID=TRUE”) in new stack
– Executing [s@macro-dial-one:37] GotoIf(“SIP/500-0000001d”, “0?usegoto,1”) in new stack
– Executing [s@macro-dial-one:38] GotoIf(“SIP/500-0000001d”, “0?godial”) in new stack
– Executing [s@macro-dial-one:39] Set(“SIP/500-0000001d”, “CONNECTEDLINE(name,i)=Barbara Brewster”) in new stack
– Executing [s@macro-dial-one:40] Set(“SIP/500-0000001d”, “CONNECTEDLINE(num)=100”) in new stack
– Executing [s@macro-dial-one:41] Set(“SIP/500-0000001d”, “D_OPTIONS=trI”) in new stack
– Executing [s@macro-dial-one:42] Dial(“SIP/500-0000001d”, “SIP/100,15,trI”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
== Extension Changed 100[ext-local] new state Ringing for Notify User 500
== Extension Changed 100[ext-local] new state Ringing for Notify User 400
== Extension Changed 100[ext-local] new state Ringing for Notify User 600
– Called SIP/100
– Connected line update to SIP/500-0000001d prevented.
== Extension Changed 100[ext-local] new state Idle for Notify User 500
== Extension Changed 100[ext-local] new state Idle for Notify User 400
== Extension Changed 100[ext-local] new state Idle for Notify User 600
== Everyone is busy/congested at this time (1:0/0/1)
– Executing [s@macro-dial-one:43] ExecIf(“SIP/500-0000001d”, “0?Set(DIALSTATUS=)”) in new stack
– Executing [s@macro-dial-one:44] GosubIf(“SIP/500-0000001d”, “0?s-CHANUNAVAIL,1()”) in new stack
– Executing [s@macro-dial-one:45] MacroExit(“SIP/500-0000001d”, “”) in new stack
– Executing [s@macro-exten-vm:8] Set(“SIP/500-0000001d”, “SV_DIALSTATUS=CHANUNAVAIL”) in new stack
– Executing [s@macro-exten-vm:9] GosubIf(“SIP/500-0000001d”, “0?docfu,1()”) in new stack
– Executing [s@macro-exten-vm:10] GosubIf(“SIP/500-0000001d”, “0?docfb,1()”) in new stack
– Executing [s@macro-exten-vm:11] Set(“SIP/500-0000001d”, “DIALSTATUS=CHANUNAVAIL”) in new stack
– Executing [s@macro-exten-vm:12] ExecIf(“SIP/500-0000001d”, “0?MacroExit()”) in new stack
– Executing [s@macro-exten-vm:13] GotoIf(“SIP/500-0000001d”, “0?s-CHANUNAVAIL,1”) in new stack
– Executing [s@macro-exten-vm:14] Macro(“SIP/500-0000001d”, “vm,100,CHANUNAVAIL,”) in new stack
– Executing [s@macro-vm:1] Macro(“SIP/500-0000001d”, “user-callerid,SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/500-0000001d”, “AMPUSER=500”) in new stack
– Executing [s@macro-user-callerid:2] GotoIf(“SIP/500-0000001d”, “13?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] GotoIf(“SIP/500-0000001d”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,26)
– Executing [s@macro-user-callerid:26] Set(“SIP/500-0000001d”, “CALLERID(number)=500”) in new stack
– Executing [s@macro-user-callerid:27] Set(“SIP/500-0000001d”, “CALLERID(name)=Tara Richards”) in new stack
– Executing [s@macro-user-callerid:28] Set(“SIP/500-0000001d”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-vm:2] Set(“SIP/500-0000001d”, “VMGAIN=”"") in new stack
– Executing [s@macro-vm:3] Macro(“SIP/500-0000001d”, “blkvm-check,”) in new stack
– Executing [s@macro-blkvm-check:1] Set(“SIP/500-0000001d”, “GOSUB_RETVAL=”) in new stack
– Executing [s@macro-blkvm-check:2] ExecIf(“SIP/500-0000001d”, “0?Set(GOSUB_RETVAL=TRUE)”) in new stack
– Executing [s@macro-blkvm-check:3] MacroExit(“SIP/500-0000001d”, “”) in new stack
– Executing [s@macro-vm:4] GotoIf(“SIP/500-0000001d”, “1?vmx,1”) in new stack
– Goto (macro-vm,vmx,1)
– Executing [vmx@macro-vm:1] Set(“SIP/500-0000001d”, “MEXTEN=100”) in new stack
– Executing [vmx@macro-vm:2] Set(“SIP/500-0000001d”, “MMODE=CHANUNAVAIL”) in new stack
– Executing [vmx@macro-vm:3] Set(“SIP/500-0000001d”, “RETVM=”) in new stack
– Executing [vmx@macro-vm:4] Set(“SIP/500-0000001d”, “MODE=unavail”) in new stack
– Executing [vmx@macro-vm:5] GotoIf(“SIP/500-0000001d”, “1?chknomsg”) in new stack
– Goto (macro-vm,vmx,8)
– Executing [vmx@macro-vm:8] GotoIf(“SIP/500-0000001d”, “0?s-CHANUNAVAIL,1”) in new stack
– Executing [vmx@macro-vm:9] GotoIf(“SIP/500-0000001d”, “1?notdirect”) in new stack
– Goto (macro-vm,vmx,11)
– Executing [vmx@macro-vm:11] NoOp(“SIP/500-0000001d”, “Checking if ext 100 is enabled: disabled”) in new stack
– Executing [vmx@macro-vm:12] GotoIf(“SIP/500-0000001d”, “1?s-CHANUNAVAIL,1”) in new stack
– Goto (macro-vm,s-CHANUNAVAIL,1)
– Executing [s-CHANUNAVAIL@macro-vm:1] Macro(“SIP/500-0000001d”, “get-vmcontext,100”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“SIP/500-0000001d”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“SIP/500-0000001d”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“SIP/500-0000001d”, “”) in new stack
– Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail(“SIP/500-0000001d”, “100@default,u”"") in new stack
– <SIP/500-0000001d> Playing ‘vm-theperson.gsm’ (language ‘en’)
– <SIP/500-0000001d> Playing ‘digits/1.gsm’ (language ‘en’)
== Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/500-0000001d’ in macro ‘vm’
== Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/500-0000001d’ in macro ‘exten-vm’
== Spawn extension (from-internal, 100, 2) exited non-zero on ‘SIP/500-0000001d’
– Executing [h@from-internal:1] Hangup(“SIP/500-0000001d”, “”) in new stack
== Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/500-0000001d’
== Extension Changed 500[ext-local] new state Idle for Notify User 100
== Extension Changed 500[ext-local] new state Idle for Notify User 400
== Extension Changed 500[ext-local] new state Idle for Notify User 600

Thanks for your response.

Hi,

What is the 100 extension user agent?
Try to set the sendrpid=no in your extensions.

There is something really strange in your system. Did you tried your configuration with Freepbx 12 and Asterisk 11?

Thank you,

Daniel Friedman
Trixton LTD.

Thanks Daniel, I ended up having two bad phones. That is what caused the channel unavailable issue.I fixed the subscription issues per your excellent advice on Send Remote Party ID setting in FreePBX.

Thank you for all of your help!

Mike

Hi Mike,

I am glad to hear that everything is working for you now.

Daniel Friedman
Trixton LTD.