Cannot call between local extensions

Hello, I have a newly installed FreePBX 13 setup. Latest updates applied. Using Yealink T46G SIP phones, chan_sip driver

The problem – certain extensions cannot call each other. The Yealink phones report “Service Unavailable”.

Specifically when dialling extension 2206 from 2207, here is the log:

[[email protected] ~]# asterisk -rvvvvvvv
Asterisk 13.4.0, Copyright (C) 1999 - 2014, Digium, Inc. and others.
Created by Mark Spencer <[email protected]>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
Connected to Asterisk 13.4.0 currently running on localhost (pid = 1628)
  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
    -- Executing [[email protected]:1] Set("SIP/2207-000000ce", "__RINGTIMER=15") in new stack
    -- Executing [[email protected]:2] Macro("SIP/2207-000000ce", "exten-vm,novm,2206,0,0,0") in new stack
    -- Executing [[email protected]:1] Macro("SIP/2207-000000ce", "user-callerid,") in new stack
    -- Executing [[email protected]:1] Set("SIP/2207-000000ce", "TOUCH_MONITOR=1438978270.8748") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "AMPUSER=2207") in new stack
    -- Executing [[email protected]:3] GotoIf("SIP/2207-000000ce", "0?report") in new stack
    -- Executing [[email protected]:4] ExecIf("SIP/2207-000000ce", "1?Set(REALCALLERIDNUM=2207)") in new stack
    -- Executing [[email protected]:5] Set("SIP/2207-000000ce", "AMPUSER=2207") in new stack
    -- Executing [[email protected]:6] GotoIf("SIP/2207-000000ce", "0?limit") in new stack
    -- Executing [[email protected]:7] Set("SIP/2207-000000ce", "AMPUSERCIDNAME=Room 2") in new stack
    -- Executing [[email protected]:8] GotoIf("SIP/2207-000000ce", "0?report") in new stack
    -- Executing [[email protected]:9] Set("SIP/2207-000000ce", "AMPUSERCID=2207") in new stack
    -- Executing [[email protected]:10] Set("SIP/2207-000000ce", "__DIAL_OPTIONS=Ttr") in new stack
    -- Executing [[email protected]:11] Set("SIP/2207-000000ce", "CALLERID(all)="Room 2" <2207>") in new stack
    -- Executing [[email protected]:12] GotoIf("SIP/2207-000000ce", "0?limit") in new stack
    -- Executing [[email protected]:13] ExecIf("SIP/2207-000000ce", "0?Set(GROUP(concurrency_limit)=2207)") in new stack
    -- Executing [[email protected]:14] GosubIf("SIP/2207-000000ce", "7?sub-ccss,s,1(macro-exten-vm,2206)") in new stack
    -- Executing [[email protected]:1] ExecIf("SIP/2207-000000ce", "0?Return()") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "CCSS_SETUP=TRUE") in new stack
    -- Executing [[email protected]:3] GosubIf("SIP/2207-000000ce", "0?monitor_config,1(macro-exten-vm,2206):monitor_default,1(macro-exten-vm,2206)") in new stack
    -- Executing [[email protected]:1] GotoIf("SIP/2207-000000ce", "1?is_exten") in new stack
    -- Goto (sub-ccss,monitor_default,4)
    -- Executing [[email protected]:4] Set("SIP/2207-000000ce", "CALLCOMPLETION(cc_monitor_policy)=generic") in new stack
    -- Executing [[email protected]:5] Set("SIP/2207-000000ce", "CALLCOMPLETION(cc_max_monitors)=5") in new stack
    -- Executing [[email protected]:6] Return("SIP/2207-000000ce", "TRUE") in new stack
    -- Executing [[email protected]:4] GosubIf("SIP/2207-000000ce", "7?agent_config,1():agent_default,1()") in new stack
    -- Executing [[email protected]:1] Set("SIP/2207-000000ce", "CALLCOMPLETION(cc_agent_policy)=generic") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "CALLCOMPLETION(cc_offer_timer)=30") in new stack
    -- Executing [[email protected]:3] Set("SIP/2207-000000ce", "CALLCOMPLETION(ccbs_available_timer)=") in new stack
    -- Executing [[email protected]:4] Set("SIP/2207-000000ce", "CALLCOMPLETION(ccnr_available_timer)=") in new stack
    -- Executing [[email protected]:5] Set("SIP/2207-000000ce", "CALLCOMPLETION(cc_callback_macro)=ccss-default") in new stack
[2015-08-07 14:11:10] WARNING[14243][C-00001114]: ccss.c:1012 ast_set_cc_callback_macro: Usage of cc_callback_macro is deprecated.  Please use cc_callback_sub instead.
    -- Executing [[email protected]:6] ExecIf("SIP/2207-000000ce", "1?Set(CALLCOMPLETION(cc_recall_timer)=)") in new stack
    -- Executing [[email protected]:7] ExecIf("SIP/2207-000000ce", "1?Set(CALLCOMPLETION(cc_max_agents)=)") in new stack
    -- Executing [[email protected]:8] ExecIf("SIP/2207-000000ce", "0?Set(CALLCOMPLETION(cc_agent_dialstring)=Local/[email protected])") in new stack
    -- Executing [[email protected]:9] Set("SIP/2207-000000ce", "CALLCOMPLETION(cc_callback_macro)=ccss-default") in new stack
[2015-08-07 14:11:10] WARNING[14243][C-00001114]: ccss.c:1012 ast_set_cc_callback_macro: Usage of cc_callback_macro is deprecated.  Please use cc_callback_sub instead.
    -- Executing [[email protected]:10] Return("SIP/2207-000000ce", "") in new stack
    -- Executing [[email protected]:5] Set("SIP/2207-000000ce", "DB(AMPUSER/2207/ccss/last_number)=2206") in new stack
    -- Executing [[email protected]:6] Return("SIP/2207-000000ce", "") in new stack
    -- Executing [[email protected]:15] ExecIf("SIP/2207-000000ce", "0?Set(CHANNEL(language)=)") in new stack
    -- Executing [[email protected]:16] GotoIf("SIP/2207-000000ce", "0?continue") in new stack
    -- Executing [[email protected]:17] ExecIf("SIP/2207-000000ce", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
    -- Executing [[email protected]:18] Set("SIP/2207-000000ce", "__TTL=64") in new stack
    -- Executing [[email protected]:19] GotoIf("SIP/2207-000000ce", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,30)
    -- Executing [[email protected]:30] Set("SIP/2207-000000ce", "CALLERID(number)=2207") in new stack
    -- Executing [[email protected]:31] Set("SIP/2207-000000ce", "CALLERID(name)=Room 2") in new stack
    -- Executing [[email protected]:32] Set("SIP/2207-000000ce", "CDR(cnum)=2207") in new stack
    -- Executing [[email protected]:33] Set("SIP/2207-000000ce", "CDR(cnam)=Room 2") in new stack
    -- Executing [[email protected]:34] Set("SIP/2207-000000ce", "CHANNEL(language)=en") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "RingGroupMethod=none") in new stack
    -- Executing [[email protected]:3] Set("SIP/2207-000000ce", "__EXTTOCALL=2206") in new stack
    -- Executing [[email protected]:4] Set("SIP/2207-000000ce", "__PICKUPMARK=2206") in new stack
    -- Executing [[email protected]:5] Set("SIP/2207-000000ce", "RT=") in new stack
    -- Executing [[email protected]:6] Gosub("SIP/2207-000000ce", "sub-record-check,s,1(exten,2206,dontcare)") in new stack
    -- Executing [[email protected]:1] GotoIf("SIP/2207-000000ce", "0?initialized") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [[email protected]:3] Set("SIP/2207-000000ce", "NOW=1438978271") in new stack
    -- Executing [[email protected]:4] Set("SIP/2207-000000ce", "__DAY=07") in new stack
    -- Executing [[email protected]:5] Set("SIP/2207-000000ce", "__MONTH=08") in new stack
    -- Executing [[email protected]:6] Set("SIP/2207-000000ce", "__YEAR=2015") in new stack
    -- Executing [[email protected]:7] Set("SIP/2207-000000ce", "__TIMESTR=20150807-141111") in new stack
    -- Executing [[email protected]:8] Set("SIP/2207-000000ce", "__FROMEXTEN=2207") in new stack
    -- Executing [[email protected]:9] Set("SIP/2207-000000ce", "__MON_FMT=wav") in new stack
    -- Executing [[email protected]:10] NoOp("SIP/2207-000000ce", "Recordings initialized") in new stack
    -- Executing [[email protected]:11] ExecIf("SIP/2207-000000ce", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [[email protected]:12] Set("SIP/2207-000000ce", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [[email protected]:13] ExecIf("SIP/2207-000000ce", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [[email protected]:14] GotoIf("SIP/2207-000000ce", "5?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [[email protected]:17] GotoIf("SIP/2207-000000ce", "1?sub-record-check,exten,1") in new stack
    -- Goto (sub-record-check,exten,1)
    -- Executing [[email protected]:1] NoOp("SIP/2207-000000ce", "Exten Recording Check between 2207 and 2206") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "CALLTYPE=internal") in new stack
    -- Executing [[email protected]:3] ExecIf("SIP/2207-000000ce", "0?Set(CALLTYPE=)") in new stack
    -- Executing [[email protected]:4] Set("SIP/2207-000000ce", "CALLEE=dontcare") in new stack
    -- Executing [[email protected]:5] ExecIf("SIP/2207-000000ce", "0?Set(CALLEE=dontcare)") in new stack
    -- Executing [[email protected]:6] GotoIf("SIP/2207-000000ce", "0?callee") in new stack
    -- Executing [[email protected]:7] GotoIf("SIP/2207-000000ce", "1?caller") in new stack
    -- Goto (sub-record-check,exten,13)
    -- Executing [[email protected]:13] Set("SIP/2207-000000ce", "RECMODE=dontcare") in new stack
    -- Executing [[email protected]:14] ExecIf("SIP/2207-000000ce", "0?Set(RECMODE=dontcare)") in new stack
    -- Executing [[email protected]:15] ExecIf("SIP/2207-000000ce", "1?Set(RECMODE=dontcare)") in new stack
    -- Executing [[email protected]:16] Gosub("SIP/2207-000000ce", "recordcheck,1(dontcare,internal,2206)") in new stack
    -- Executing [[email protected]:1] NoOp("SIP/2207-000000ce", "Starting recording check against dontcare") in new stack
    -- Executing [[email protected]:2] Goto("SIP/2207-000000ce", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
    -- Executing [[email protected]:3] Return("SIP/2207-000000ce", "") in new stack
    -- Executing [[email protected]:17] Return("SIP/2207-000000ce", "") in new stack
    -- Executing [[email protected]:7] GotoIf("SIP/2207-000000ce", "1?macrodial") in new stack
    -- Goto (macro-exten-vm,s,13)
    -- Executing [[email protected]:13] GosubIf("SIP/2207-000000ce", "0?clrheader,1()") in new stack
    -- Executing [[email protected]:14] Macro("SIP/2207-000000ce", "dial-one,,Ttr,2206") in new stack
    -- Executing [[email protected]:1] Set("SIP/2207-000000ce", "DEXTEN=2206") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "DIALSTATUS_CW=") in new stack
    -- Executing [[email protected]:3] GosubIf("SIP/2207-000000ce", "0?screen,1()") in new stack
    -- Executing [[email protected]:4] GosubIf("SIP/2207-000000ce", "0?cf,1()") in new stack
    -- Executing [[email protected]:5] GotoIf("SIP/2207-000000ce", "1?skip1") in new stack
    -- Goto (macro-dial-one,s,8)
    -- Executing [[email protected]:8] GotoIf("SIP/2207-000000ce", "0?nodial") in new stack
    -- Executing [[email protected]:9] GotoIf("SIP/2207-000000ce", "0?continue") in new stack
    -- Executing [[email protected]:10] Set("SIP/2207-000000ce", "EXTHASCW=ENABLED") in new stack
    -- Executing [[email protected]:11] GotoIf("SIP/2207-000000ce", "0?next1:cwinusebusy") in new stack
    -- Goto (macro-dial-one,s,23)
    -- Executing [[email protected]:23] GotoIf("SIP/2207-000000ce", "0?next3:continue") in new stack
    -- Goto (macro-dial-one,s,25)
    -- Executing [[email protected]:25] GotoIf("SIP/2207-000000ce", "0?nodial") in new stack
    -- Executing [[email protected]:26] GosubIf("SIP/2207-000000ce", "1?dstring,1():dlocal,1()") in new stack
    -- Executing [[email protected]:1] Set("SIP/2207-000000ce", "DSTRING=") in new stack
    -- Executing [[email protected]:2] Set("SIP/2207-000000ce", "DEVICES=") in new stack
    -- Executing [[email protected]:3] ExecIf("SIP/2207-000000ce", "1?Return()") in new stack
    -- Executing [[email protected]:27] GotoIf("SIP/2207-000000ce", "1?nodial") in new stack
    -- Goto (macro-dial-one,s,48)
    -- Executing [[email protected]:48] ExecIf("SIP/2207-000000ce", "1?Set(DIALSTATUS=NOANSWER)") in new stack
    -- Executing [[email protected]:49] NoOp("SIP/2207-000000ce", "Returned from dial-one with nothing to call and DIALSTATUS: NOANSWER") in new stack
    -- Executing [[email protected]:50] MacroExit("SIP/2207-000000ce", "") in new stack
    -- Executing [[email protected]:15] Set("SIP/2207-000000ce", "SV_DIALSTATUS=NOANSWER") in new stack
    -- Executing [[email protected]:16] GosubIf("SIP/2207-000000ce", "0?docfu,1()") in new stack
    -- Executing [[email protected]:17] GosubIf("SIP/2207-000000ce", "0?docfb,1()") in new stack
    -- Executing [[email protected]:18] Set("SIP/2207-000000ce", "DIALSTATUS=NOANSWER") in new stack
    -- Executing [[email protected]:19] ExecIf("SIP/2207-000000ce", "0?MacroExit()") in new stack
    -- Executing [[email protected]:20] GotoIf("SIP/2207-000000ce", "1?s-NOANSWER,1") in new stack
    -- Goto (macro-exten-vm,s-NOANSWER,1)
    -- Executing [[email protected]:1] GotoIf("SIP/2207-000000ce", "0?exit,1") in new stack
    -- Executing [[email protected]:2] PlayTones("SIP/2207-000000ce", "congestion") in new stack
    -- Executing [[email protected]:3] Congestion("SIP/2207-000000ce", "10") in new stack
  == Spawn extension (macro-exten-vm, s-NOANSWER, 3) exited non-zero on 'SIP/2207-000000ce' in macro 'exten-vm'
  == Spawn extension (from-internal, 2206, 2) exited non-zero on 'SIP/2207-000000ce'
    -- Executing [[email protected]:1] Hangup("SIP/2207-000000ce", "") in new stack
  == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/2207-000000ce'

And here is an excerpt from sip show peers for the affected extensions:

localhost*CLI> sip show peers
Name/username             Host                                    Dyn Forcerport Comedia    ACL Port     Status      Description                      
2206/2206                 10.100.2.7                               D  No         No          A  5061     OK (77 ms)                                   
2207/2207                 10.100.2.3                               D  No         No          A  5061     OK (73 ms)                 

Both extensions can dial out fine - they just can’t call each other.

Note that the phones are on a different subnet (10.100.0.x) from the FreePBX server (10.0.100.12) but they are all connected via VPN so all IPs are ‘local’ to each other and can ping between each other.

The extensions are configured with commercial Endpoint Manager and do not have voicemail enabled.

Any suggestions?

Ok, so I discovered that if I enable voicemail on the target extension (2206) and then disable it again, I can then call between the extensions without any issue. Any idea why this would be? Is this a bug that should be filed for FreePBX 13 ?

Sounds like NAT could be the culprit here.

The best tool in the world (well, I only recently discovered it) is ngrep for troubleshooting SIP. Get it from EPEL or wherever you want, fire that up watching either a particular IP (which can be noisy) or port and see exactly what is contained in the SIP SDP’s - this will quickly point you to what might be going wrong.