OS=CentOS-6.3 (freepbx)
Asterisk-11.3.0
FreePBX-2.11.0.0rc1.5
Arch=x86_64
I am encountering the following when I try and dial one registered extension to another. Our FreePBX installation is set up with Devices and Users. These particular extensions have a default user assigned. The default userid and the extension id have the same value in this case (41710/41710 and 41711/41711)
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
[2013-05-10 14:47:35] DEBUG[25839][C-00000036]: sip/sdp_crypto.c:285 sdp_crypto_process: Accepting crypto tag 1
[2013-05-10 14:47:35] DEBUG[25839][C-00000036]: sip/sdp_crypto.c:310 sdp_crypto_offer: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:KZ4358ExTz1kD7XY0agBBPxRaqazeClf1ThLMavN
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "__RINGTIMER=15") in new stack
-- Executing [[email protected]:2] Macro("SIP/41711-0000003b", "exten-vm,novm,41710,0,0,0") in new stack
-- Executing [[email protected]:1] Macro("SIP/41711-0000003b", "user-callerid,") in new stack
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "TOUCH_MONITOR=1368211655.80") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "AMPUSER=41711") in new stack
-- Executing [[email protected]:3] GotoIf("SIP/41711-0000003b", "0?report") in new stack
-- Executing [[email protected]:4] ExecIf("SIP/41711-0000003b", "1?Set(REALCALLERIDNUM=41711)") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "AMPUSER=41711") in new stack
-- Executing [[email protected]:6] Set("SIP/41711-0000003b", "AMPUSERCIDNAME=User 11") in new stack
-- Executing [[email protected]:7] GotoIf("SIP/41711-0000003b", "0?report") in new stack
-- Executing [[email protected]:8] Set("SIP/41711-0000003b", "AMPUSERCID=41711") in new stack
-- Executing [[email protected]:9] Set("SIP/41711-0000003b", "__DIAL_OPTIONS=Ttr") in new stack
-- Executing [[email protected]:10] Set("SIP/41711-0000003b", "CALLERID(all)="User 11" <41711>") in new stack
-- Executing [[email protected]:11] GotoIf("SIP/41711-0000003b", "0?limit") in new stack
-- Executing [[email protected]:12] ExecIf("SIP/41711-0000003b", "0?Set(GROUP(concurrency_limit)=41711)") in new stack
-- Executing [[email protected]:13] ExecIf("SIP/41711-0000003b", "0?Set(CHANNEL(language)=)") in new stack
-- Executing [[email protected]:14] GosubIf("SIP/41711-0000003b", "7?sub-ccss,s,1(macro-exten-vm,41710)") in new stack
-- Executing [[email protected]:1] ExecIf("SIP/41711-0000003b", "0?Return()") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "CCSS_SETUP=TRUE") in new stack
-- Executing [[email protected]:3] GosubIf("SIP/41711-0000003b", "0?monitor_config,1(macro-exten-vm,41710):monitor_default,1(macro-exten-vm,41710)") in new stack
-- Executing [[email protected]:1] GotoIf("SIP/41711-0000003b", "1?is_exten") in new stack
-- Goto (sub-ccss,monitor_default,4)
-- Executing [[email protected]:4] Set("SIP/41711-0000003b", "CALLCOMPLETION(cc_monitor_policy)=generic") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "CALLCOMPLETION(cc_max_monitors)=5") in new stack
-- Executing [[email protected]:6] Return("SIP/41711-0000003b", "TRUE") in new stack
-- Executing [[email protected]:4] GosubIf("SIP/41711-0000003b", "7?agent_config,1():agent_default,1()") in new stack
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "CALLCOMPLETION(cc_agent_policy)=generic") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "CALLCOMPLETION(cc_offer_timer)=30") in new stack
-- Executing [[email protected]:3] Set("SIP/41711-0000003b", "CALLCOMPLETION(ccbs_available_timer)=") in new stack
-- Executing [[email protected]:4] Set("SIP/41711-0000003b", "CALLCOMPLETION(ccnr_available_timer)=") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "CALLCOMPLETION(cc_callback_macro)=ccss-default") in new stack
[2013-05-10 14:47:35] WARNING[14438][C-00000036]: ccss.c:1000 ast_set_cc_callback_macro: Usage of cc_callback_macro is deprecated. Please use cc_callback_sub instead.
[2013-05-10 14:47:35] WARNING[14438][C-00000036]: ccss.c:1000 ast_set_cc_callback_macro: Usage of cc_callback_macro is deprecated. Please use cc_callback_sub instead.
-- Executing [[email protected]:6] ExecIf("SIP/41711-0000003b", "1?Set(CALLCOMPLETION(cc_recall_timer)=)") in new stack
-- Executing [[email protected]:7] ExecIf("SIP/41711-0000003b", "1?Set(CALLCOMPLETION(cc_max_agents)=)") in new stack
-- Executing [[email protected]:8] ExecIf("SIP/41711-0000003b", "0?Set(CALLCOMPLETION(cc_agent_dialstring)=Local/[email protected])") in new stack
-- Executing [[email protected]:9] Set("SIP/41711-0000003b", "CALLCOMPLETION(cc_callback_macro)=ccss-default") in new stack
[2013-05-10 14:47:35] WARNING[14438][C-00000036]: ccss.c:1000 ast_set_cc_callback_macro: Usage of cc_callback_macro is deprecated. Please use cc_callback_sub instead.
[2013-05-10 14:47:35] WARNING[14438][C-00000036]: ccss.c:1000 ast_set_cc_callback_macro: Usage of cc_callback_macro is deprecated. Please use cc_callback_sub instead.
-- Executing [[email protected]:10] Return("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "DB(AMPUSER/41711/ccss/last_number)=41710") in new stack
-- Executing [[email protected]:6] Return("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:15] GotoIf("SIP/41711-0000003b", "0?continue") in new stack
-- Executing [[email protected]:16] Set("SIP/41711-0000003b", "__TTL=64") in new stack
-- Executing [[email protected]:17] GotoIf("SIP/41711-0000003b", "1?continue") in new stack
-- Goto (macro-user-callerid,s,28)
-- Executing [[email protected]:28] Set("SIP/41711-0000003b", "CALLERID(number)=41711") in new stack
-- Executing [[email protected]:29] Set("SIP/41711-0000003b", "CALLERID(name)=User 11") in new stack
-- Executing [[email protected]:30] Set("SIP/41711-0000003b", "CDR(cnum)=41711") in new stack
-- Executing [[email protected]:31] Set("SIP/41711-0000003b", "CDR(cnam)=User 11") in new stack
-- Executing [[email protected]:32] Set("SIP/41711-0000003b", "CHANNEL(language)=en") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "RingGroupMethod=none") in new stack
-- Executing [[email protected]:3] Set("SIP/41711-0000003b", "__EXTTOCALL=41710") in new stack
-- Executing [[email protected]:4] Set("SIP/41711-0000003b", "__PICKUPMARK=41710") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "RT=") in new stack
-- Executing [[email protected]:6] Gosub("SIP/41711-0000003b", "sub-record-check,s,1(exten,41710,)") in new stack
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [[email protected]:2] GotoIf("SIP/41711-0000003b", "1?check") in new stack
-- Goto (sub-record-check,s,7)
-- Executing [[email protected]:7] Set("SIP/41711-0000003b", "__MON_FMT=wav") in new stack
-- Executing [[email protected]:8] GotoIf("SIP/41711-0000003b", "1?next") in new stack
-- Goto (sub-record-check,s,11)
-- Executing [[email protected]:11] ExecIf("SIP/41711-0000003b", "0?Return()") in new stack
-- Executing [[email protected]:12] ExecIf("SIP/41711-0000003b", "0?Set(__REC_POLICY_MODE=)") in new stack
-- Executing [[email protected]:13] GotoIf("SIP/41711-0000003b", "0?exten,1") in new stack
-- Executing [[email protected]:14] Set("SIP/41711-0000003b", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [[email protected]:15] Set("SIP/41711-0000003b", "NOW=1368211655") in new stack
-- Executing [[email protected]:16] Set("SIP/41711-0000003b", "__DAY=10") in new stack
-- Executing [[email protected]:17] Set("SIP/41711-0000003b", "__MONTH=05") in new stack
-- Executing [[email protected]:18] Set("SIP/41711-0000003b", "__YEAR=2013") in new stack
-- Executing [[email protected]:19] Set("SIP/41711-0000003b", "__TIMESTR=20130510-144735") in new stack
-- Executing [[email protected]:20] Set("SIP/41711-0000003b", "__FROMEXTEN=41711") in new stack
-- Executing [[email protected]:21] Set("SIP/41711-0000003b", "__CALLFILENAME=exten-41710-41711-20130510-144735-1368211655.80") in new stack
-- Executing [[email protected]:22] Goto("SIP/41711-0000003b", "exten,1") in new stack
-- Goto (sub-record-check,exten,1)
-- Executing [[email protected]:1] GotoIf("SIP/41711-0000003b", "0?callee") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "__REC_POLICY_MODE=dontcare") in new stack
-- Executing [[email protected]:3] GotoIf("SIP/41711-0000003b", "1?caller") in new stack
-- Goto (sub-record-check,exten,10)
-- Executing [[email protected]:10] Set("SIP/41711-0000003b", "__REC_POLICY_MODE=dontcare") in new stack
-- Executing [[email protected]:11] GosubIf("SIP/41711-0000003b", "0?record,1(exten,41710,41711)") in new stack
-- Executing [[email protected]:12] Return("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:7] GotoIf("SIP/41711-0000003b", "1?macrodial") in new stack
-- Goto (macro-exten-vm,s,13)
-- Executing [[email protected]:13] GosubIf("SIP/41711-0000003b", "0?clrheader,1()") in new stack
-- Executing [[email protected]:14] Macro("SIP/41711-0000003b", "dial-one,,Ttr,41710") in new stack
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "DEXTEN=41710") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "DIALSTATUS_CW=") in new stack
-- Executing [[email protected]:3] GosubIf("SIP/41711-0000003b", "0?screen,1()") in new stack
-- Executing [[email protected]:4] GosubIf("SIP/41711-0000003b", "0?cf,1()") in new stack
-- Executing [[email protected]:5] GotoIf("SIP/41711-0000003b", "1?skip1") in new stack
-- Goto (macro-dial-one,s,8)
-- Executing [[email protected]:8] GotoIf("SIP/41711-0000003b", "0?nodial") in new stack
-- Executing [[email protected]:9] GotoIf("SIP/41711-0000003b", "0?continue") in new stack
-- Executing [[email protected]:10] Set("SIP/41711-0000003b", "EXTHASCW=ENABLED") in new stack
-- Executing [[email protected]:11] GotoIf("SIP/41711-0000003b", "0?next1:cwinusebusy") in new stack
-- Goto (macro-dial-one,s,23)
-- Executing [[email protected]:23] GotoIf("SIP/41711-0000003b", "1?next3:continue") in new stack
-- Goto (macro-dial-one,s,24)
-- Executing [[email protected]:24] ExecIf("SIP/41711-0000003b", "0?Set(DIALSTATUS_CW=BUSY)") in new stack
-- Executing [[email protected]:25] GotoIf("SIP/41711-0000003b", "0?nodial") in new stack
-- Executing [[email protected]:26] GosubIf("SIP/41711-0000003b", "1?dstring,1():dlocal,1()") in new stack
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "DSTRING=") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "DEVICES=41710") in new stack
-- Executing [[email protected]:3] ExecIf("SIP/41711-0000003b", "0?Return()") in new stack
-- Executing [[email protected]:4] ExecIf("SIP/41711-0000003b", "0?Set(DEVICES=1710)") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "LOOPCNT=1") in new stack
-- Executing [[email protected]:6] Set("SIP/41711-0000003b", "ITER=1") in new stack
-- Executing [[email protected]:7] Set("SIP/41711-0000003b", "THISDIAL=SIP/41710") in new stack
-- Executing [[email protected]:8] GosubIf("SIP/41711-0000003b", "1?zap2dahdi,1()") in new stack
-- Executing [[email protected]:1] ExecIf("SIP/41711-0000003b", "0?Return()") in new stack
-- Executing [[email protected]:2] Set("SIP/41711-0000003b", "NEWDIAL=") in new stack
-- Executing [[email protected]:3] Set("SIP/41711-0000003b", "LOOPCNT2=1") in new stack
-- Executing [[email protected]:4] Set("SIP/41711-0000003b", "ITER2=1") in new stack
-- Executing [[email protected]:5] Set("SIP/41711-0000003b", "THISPART2=SIP/41710") in new stack
-- Executing [[email protected]:6] ExecIf("SIP/41711-0000003b", "0?Set(THISPART2=DAHDI/41710)") in new stack
-- Executing [[email protected]:7] Set("SIP/41711-0000003b", "NEWDIAL=SIP/41710&") in new stack
-- Executing [[email protected]:8] Set("SIP/41711-0000003b", "ITER2=2") in new stack
-- Executing [[email protected]:9] GotoIf("SIP/41711-0000003b", "0?begin2") in new stack
-- Executing [[email protected]:10] Set("SIP/41711-0000003b", "THISDIAL=SIP/41710") in new stack
-- Executing [[email protected]:11] Return("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:9] Set("SIP/41711-0000003b", "DSTRING=SIP/41710&") in new stack
-- Executing [[email protected]:10] Set("SIP/41711-0000003b", "ITER=2") in new stack
-- Executing [[email protected]:11] GotoIf("SIP/41711-0000003b", "0?begin") in new stack
-- Executing [[email protected]:12] Set("SIP/41711-0000003b", "DSTRING=SIP/41710") in new stack
-- Executing [[email protected]:13] Return("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:27] GotoIf("SIP/41711-0000003b", "0?nodial") in new stack
-- Executing [[email protected]:28] GotoIf("SIP/41711-0000003b", "0?skiptrace") in new stack
-- Executing [[email protected]:29] GosubIf("SIP/41711-0000003b", "1?ctset,1():ctclear,1()") in new stack
-- Executing [[email protected]:1] Set("SIP/41711-0000003b", "DB(CALLTRACE/41710)=41711") in new stack
-- Executing [[email protected]:2] Return("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:30] Set("SIP/41711-0000003b", "D_OPTIONS=Ttr") in new stack
-- Executing [[email protected]:31] ExecIf("SIP/41711-0000003b", "0?SIPAddHeader(Alert-Info: )") in new stack
-- Executing [[email protected]:32] ExecIf("SIP/41711-0000003b", "0?SIPAddHeader()") in new stack
-- Executing [[email protected]:33] ExecIf("SIP/41711-0000003b", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [[email protected]:34] GosubIf("SIP/41711-0000003b", "0?qwait,1()") in new stack
-- Executing [[email protected]:35] Set("SIP/41711-0000003b", "__CWIGNORE=") in new stack
-- Executing [[email protected]:36] Set("SIP/41711-0000003b", "__KEEPCID=TRUE") in new stack
-- Executing [[email protected]:37] GotoIf("SIP/41711-0000003b", "0?usegoto,1") in new stack
-- Executing [[email protected]:38] GotoIf("SIP/41711-0000003b", "0?godial") in new stack
-- Executing [[email protected]:39] Set("SIP/41711-0000003b", "CONNECTEDLINE(name,i)=Reception") in new stack
-- Executing [[email protected]:40] Set("SIP/41711-0000003b", "CONNECTEDLINE(num)=41710") in new stack
-- Executing [[email protected]:41] Set("SIP/41711-0000003b", "D_OPTIONS=TtrI") in new stack
-- Executing [[email protected]:42] Dial("SIP/41711-0000003b", "SIP/41710,,TtrI") in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
[2013-05-10 14:47:35] DEBUG[14438][C-00000036]: sip/sdp_crypto.c:310 sdp_crypto_offer: Crypto line: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:7Fd9nJ+Jxe1ceGpeq8mBX2JC0pEpV2vUwJdXqp9r
-- Called SIP/41710
-- Connected line update to SIP/41711-0000003b prevented.
[2013-05-10 14:47:35] WARNING[25839][C-00000036]: chan_sip.c:22795 handle_response_invite: Received response: "Forbidden" from '"User 11" ;tag=as7d6d20c3'
[2013-05-10 14:47:35] WARNING[25839][C-00000036]: chan_sip.c:22795 handle_response_invite: Received response: "Forbidden" from '"User 11" ;tag=as7d6d20c3'
== Everyone is busy/congested at this time (1:0/0/1)
-- Executing [[email protected]:43] ExecIf("SIP/41711-0000003b", "0?MacroExit()") in new stack
-- Executing [[email protected]:44] ExecIf("SIP/41711-0000003b", "0?Set(DIALSTATUS=)") in new stack
-- Executing [[email protected]:45] GosubIf("SIP/41711-0000003b", "0?s-CHANUNAVAIL,1()") in new stack
-- Executing [[email protected]:46] MacroExit("SIP/41711-0000003b", "") in new stack
-- Executing [[email protected]:15] Set("SIP/41711-0000003b", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
-- Executing [[email protected]:16] GosubIf("SIP/41711-0000003b", "0?docfu,1()") in new stack
-- Executing [[email protected]:17] GosubIf("SIP/41711-0000003b", "0?docfb,1()") in new stack
-- Executing [[email protected]:18] Set("SIP/41711-0000003b", "DIALSTATUS=CHANUNAVAIL") in new stack
-- Executing [[email protected]:19] ExecIf("SIP/41711-0000003b", "0?MacroExit()") in new stack
-- Executing [[email protected]:20] GotoIf("SIP/41711-0000003b", "1?s-CHANUNAVAIL,1") in new stack
-- Goto (macro-exten-vm,s-CHANUNAVAIL,1)
-- Executing [[email protected]:1] GotoIf("SIP/41711-0000003b", "0?exit,1") in new stack
-- Executing [[email protected]:2] PlayTones("SIP/41711-0000003b", "congestion") in new stack
-- Executing [[email protected]:3] Congestion("SIP/41711-0000003b", "10") in new stack
== Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 3) exited non-zero on 'SIP/41711-0000003b' in macro 'exten-vm'
== Spawn extension (from-internal, 41710, 2) exited non-zero on 'SIP/41711-0000003b'
-- Executing [[email protected]:1] Hangup("SIP/41711-0000003b", "") in new stack
== Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/41711-0000003b'
This is the system state:
CLI> sip show peers Name/username Host Dyn Forcerport ACL Port Status Description 41710/41710 192.168.6.110 D A 2057 OK (20 ms) 41711/41711 192.168.6.111 D A 3072 OK (4 ms) 41712 90012/90012 . . . 192.168.6.119 D A 5060 OK (1 ms) 12 sip peers [Monitored: 3 online, 9 offline Unmonitored: 0 online, 0 offline]
Now I can guess that this is a configuration problem of my own making but as this is all new to me I naturally have no idea what it might be.
Both sets are snom units (a 320 and an 870). Both belong to the same ring group. We have fax detection enabled on the incoming route but that should not figure in this problem.
Any help would be appreciated.