Outbound route busy and inbound route disconnects

oingare · July 12, 2013, 1:49am

Hi,

I have struggled for weeks to get to this point and I can almost smell the finish line…
Any help/pointers would be appreciated!
I have read the manuals and startup guides but I must be missing something obvious

Problem: I cannot make outgoing calls and I cannot reach extensions when calling from the outside

I have the following setup:

4 Cisco 7961s that work fine internally where I can call/answer between them.
PBX Firmware: 4.211.64-2
PBX Service Pack: 1.0.0.0
Linux Distribution: (Redhat CentOS release 6.4 (Final)), FreePBX version: (2.11.0)
TMG firewall with SIP filter
I added a SIP trunk that seems to register just fine with skype (Asterisk (Ver. 11.3.0): Registries: 1 SIP registrations.
I added an inbound route
I added an outgoing route
I added an IVR
I set the IVR as the destination for inbound calls ( I also tried to set the destination to an extension with the same result)

Below are the logs for both inbound and outbound attempts
replaced my phone with 1112223333 to make it generic

inbound: (rings a few times, call starts with silence, disconnects after 15 secs)
chan_sip.c: Peer ‘400’ is now Reachable. (29ms / 2000ms)
netsock2.c: == Using SIP RTP TOS bits 184
netsock2.c: == Using SIP RTP CoS mark 5
pbx.c: – Executing [11112223333@from-sip-external:1] NoOp(“SIP/sip.skype.com-00000058”, “Received incoming SIP connection from unknown peer to 11112223333”) in new stack
pbx.c: – Executing [11112223333@from-sip-external:2] Set(“SIP/sip.skype.com-00000058”, “DID=11112223333”) in new stack
pbx.c: – Executing [11112223333@from-sip-external:3] Goto(“SIP/sip.skype.com-00000058”, “s,1”) in new stack
pbx.c: – Goto (from-sip-external,s,1)
pbx.c: – Executing [s@from-sip-external:1] GotoIf(“SIP/sip.skype.com-00000058”, “0?checklang:noanonymous”) in new stack
pbx.c: – Goto (from-sip-external,s,5)
pbx.c: – Executing [s@from-sip-external:5] Set(“SIP/sip.skype.com-00000058”, “TIMEOUT(absolute)=15”) in new stack
func_timeout.c: – Channel will hangup at 2013-07-11 20:23:31.840 EDT.
pbx.c: – Executing [s@from-sip-external:6] Answer(“SIP/sip.skype.com-00000058”, “”) in new stack
pbx.c: – Executing [s@from-sip-external:7] Wait(“SIP/sip.skype.com-00000058”, “2”) in new stack
pbx.c: – Executing [s@from-sip-external:8] Playback(“SIP/sip.skype.com-00000058”, “ss-noservice”) in new stack
file.c: – <SIP/sip.skype.com-00000058> Playing ‘ss-noservice.ulaw’ (language ‘en’)
pbx.c: – Executing [s@from-sip-external:9] PlayTones(“SIP/sip.skype.com-00000058”, “congestion”) in new stack
pbx.c: – Executing [s@from-sip-external:10] Congestion(“SIP/sip.skype.com-00000058”, “5”) in new stack
pbx.c: == Spawn extension (from-sip-external, s, 10) exited non-zero on 'SIP/sip.skype.com-00000058’
pbx.c: – Executing [h@from-sip-external:1] Hangup(“SIP/sip.skype.com-00000058”, “”) in new stack
pbx.c: == Spawn extension (from-sip-external, h, 1) exited non-zero on ‘SIP/sip.skype.com-00000058’

outbound: (busy signal)
chan_sip.c: Peer ‘400’ is now Reachable. (29ms / 2000ms)
netsock2.c: == Using SIP RTP TOS bits 184
netsock2.c: == Using SIP RTP CoS mark 5
pbx.c: – Executing [11112223333@from-sip-external:1] NoOp(“SIP/sip.skype.com-00000058”, “Received incoming SIP connection from unknown peer to 11112223333”) in new stack
pbx.c: – Executing [11112223333@from-sip-external:2] Set(“SIP/sip.skype.com-00000058”, “DID=11112223333”) in new stack
pbx.c: – Executing [11112223333@from-sip-external:3] Goto(“SIP/sip.skype.com-00000058”, “s,1”) in new stack
pbx.c: – Goto (from-sip-external,s,1)
pbx.c: – Executing [s@from-sip-external:1] GotoIf(“SIP/sip.skype.com-00000058”, “0?checklang:noanonymous”) in new stack
pbx.c: – Goto (from-sip-external,s,5)
pbx.c: – Executing [s@from-sip-external:5] Set(“SIP/sip.skype.com-00000058”, “TIMEOUT(absolute)=15”) in new stack
func_timeout.c: – Channel will hangup at 2013-07-11 20:23:31.840 EDT.
pbx.c: – Executing [s@from-sip-external:6] Answer(“SIP/sip.skype.com-00000058”, “”) in new stack
pbx.c: – Executing [s@from-sip-external:7] Wait(“SIP/sip.skype.com-00000058”, “2”) in new stack
pbx.c: – Executing [s@from-sip-external:8] Playback(“SIP/sip.skype.com-00000058”, “ss-noservice”) in new stack
file.c: – <SIP/sip.skype.com-00000058> Playing ‘ss-noservice.ulaw’ (language ‘en’)
pbx.c: – Executing [s@from-sip-external:9] PlayTones(“SIP/sip.skype.com-00000058”, “congestion”) in new stack
pbx.c: – Executing [s@from-sip-external:10] Congestion(“SIP/sip.skype.com-00000058”, “5”) in new stack
pbx.c: == Spawn extension (from-sip-external, s, 10) exited non-zero on 'SIP/sip.skype.com-00000058’
pbx.c: – Executing [h@from-sip-external:1] Hangup(“SIP/sip.skype.com-00000058”, “”) in new stack
pbx.c: == Spawn extension (from-sip-external, h, 1) exited non-zero on 'SIP/sip.skype.com-00000058’
netsock2.c: == Using SIP RTP TOS bits 184
netsock2.c: == Using SIP RTP CoS mark 5
pbx.c: – Executing [18885551212@from-internal:1] Macro(“SIP/400-00000059”, “user-callerid,LIMIT,”) in new stack
pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/400-00000059”, “TOUCH_MONITOR=1373588735.97”) in new stack
pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/400-00000059”, “AMPUSER=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/400-00000059”, “0?report”) in new stack
pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/400-00000059”, “1?Set(REALCALLERIDNUM=400)”) in new stack
pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/400-00000059”, “AMPUSER=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:6] Set(“SIP/400-00000059”, “AMPUSERCIDNAME=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:7] GotoIf(“SIP/400-00000059”, “0?report”) in new stack
pbx.c: – Executing [s@macro-user-callerid:8] Set(“SIP/400-00000059”, “AMPUSERCID=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:9] Set(“SIP/400-00000059”, “__DIAL_OPTIONS=Ttr”) in new stack
pbx.c: – Executing [s@macro-user-callerid:10] Set(“SIP/400-00000059”, “CALLERID(all)=“400” <400>”) in new stack
pbx.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/400-00000059”, “0?limit”) in new stack
pbx.c: – Executing [s@macro-user-callerid:12] ExecIf(“SIP/400-00000059”, “1?Set(GROUP(concurrency_limit)=400)”) in new stack
pbx.c: – Executing [s@macro-user-callerid:13] GosubIf(“SIP/400-00000059”, “7?sub-ccss,s,1(from-internal,18885551212)”) in new stack
pbx.c: – Executing [s@sub-ccss:1] ExecIf(“SIP/400-00000059”, “0?Return()”) in new stack
pbx.c: – Executing [s@sub-ccss:2] Set(“SIP/400-00000059”, “CCSS_SETUP=TRUE”) in new stack
pbx.c: – Executing [s@sub-ccss:3] GosubIf(“SIP/400-00000059”, “0?monitor_config,1(from-internal,18885551212):monitor_default,1(from-internal,18885551212)”) in new stack
pbx.c: – Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/400-00000059”, “0?is_exten”) in new stack
pbx.c: – Executing [monitor_default@sub-ccss:2] StackPop(“SIP/400-00000059”, “”) in new stack
pbx.c: – Executing [monitor_default@sub-ccss:3] Return(“SIP/400-00000059”, “FALSE”) in new stack
pbx.c: – Executing [s@macro-user-callerid:14] ExecIf(“SIP/400-00000059”, “0?Set(CHANNEL(language)=)”) in new stack
pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/400-00000059”, “1?continue”) in new stack
pbx.c: – Goto (macro-user-callerid,s,28)
pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/400-00000059”, “CALLERID(number)=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/400-00000059”, “CALLERID(name)=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/400-00000059”, “CDR(cnum)=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/400-00000059”, “CDR(cnam)=400”) in new stack
pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/400-00000059”, “CHANNEL(language)=en”) in new stack
pbx.c: – Executing [18885551212@from-internal:2] Set(“SIP/400-00000059”, “MOHCLASS=none”) in new stack
pbx.c: – Executing [18885551212@from-internal:3] ExecIf(“SIP/400-00000059”, “1?Set(TRUNKCIDOVERRIDE=1112223333)”) in new stack
pbx.c: – Executing [18885551212@from-internal:4] Set(“SIP/400-00000059”, “_NODEST=”) in new stack
pbx.c: – Executing [18885551212@from-internal:5] Gosub(“SIP/400-00000059”, “sub-record-check,s,1(out,18885551212,)”) in new stack
pbx.c: – Executing [s@sub-record-check:1] Set(“SIP/400-00000059”, “REC_POLICY_MODE_SAVE=”) in new stack
pbx.c: – Executing [s@sub-record-check:2] GotoIf(“SIP/400-00000059”, “1?check”) in new stack
pbx.c: – Goto (sub-record-check,s,7)
pbx.c: – Executing [s@sub-record-check:7] Set(“SIP/400-00000059”, “__MON_FMT=wav”) in new stack
pbx.c: – Executing [s@sub-record-check:8] GotoIf(“SIP/400-00000059”, “1?next”) in new stack
pbx.c: – Goto (sub-record-check,s,11)
pbx.c: – Executing [s@sub-record-check:11] ExecIf(“SIP/400-00000059”, “0?Return()”) in new stack
pbx.c: – Executing [s@sub-record-check:12] ExecIf(“SIP/400-00000059”, “0?Set(__REC_POLICY_MODE=)”) in new stack
pbx.c: – Executing [s@sub-record-check:13] GotoIf(“SIP/400-00000059”, “0?out,1”) in new stack
pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/400-00000059”, “__REC_STATUS=INITIALIZED”) in new stack
pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/400-00000059”, “NOW=1373588735”) in new stack
pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/400-00000059”, “__DAY=11”) in new stack
pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/400-00000059”, “__MONTH=07”) in new stack
pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/400-00000059”, “__YEAR=2013”) in new stack
pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/400-00000059”, “__TIMESTR=20130711-202535”) in new stack
pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/400-00000059”, “__FROMEXTEN=400”) in new stack
pbx.c: – Executing [s@sub-record-check:21] Set(“SIP/400-00000059”, “__CALLFILENAME=out-18885551212-400-20130711-202535-1373588735.97”) in new stack
pbx.c: – Executing [s@sub-record-check:22] Goto(“SIP/400-00000059”, “out,1”) in new stack
pbx.c: – Goto (sub-record-check,out,1)
pbx.c: – Executing [out@sub-record-check:1] ExecIf(“SIP/400-00000059”, “1?Set(__REC_POLICY_MODE=dontcare)”) in new stack
pbx.c: – Executing [out@sub-record-check:2] GosubIf(“SIP/400-00000059”, “0?record,1(exten,18885551212,400)”) in new stack
pbx.c: – Executing [out@sub-record-check:3] Return(“SIP/400-00000059”, “”) in new stack
pbx.c: – Executing [18885551212@from-internal:6] Macro(“SIP/400-00000059”, “dialout-trunk,2,18885551212,off”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/400-00000059”, “DIAL_TRUNK=2”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/400-00000059”, “0?sub-pincheck,s,1()”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/400-00000059”, “0?disabletrunk,1”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/400-00000059”, “DIAL_NUMBER=18885551212”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/400-00000059”, “DIAL_TRUNK_OPTIONS=Ttr”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/400-00000059”, “OUTBOUND_GROUP=OUT_2”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/400-00000059”, “0?nomax”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:8] GotoIf(“SIP/400-00000059”, “0?chanfull”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/400-00000059”, “0?skipoutcid”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/400-00000059”, “DIAL_TRUNK_OPTIONS=Tt”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/400-00000059”, “outbound-callerid,2”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/400-00000059”, “0?Set(CALLERPRES()=)”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/400-00000059”, “0?Set(REALCALLERIDNUM=400)”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/400-00000059”, “1?normcid”) in new stack
pbx.c: – Goto (macro-outbound-callerid,s,6)
pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/400-00000059”, “USEROUTCID=”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/400-00000059”, “EMERGENCYCID=”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/400-00000059”, “TRUNKOUTCID=8885551212”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/400-00000059”, “1?trunkcid”) in new stack
pbx.c: – Goto (macro-outbound-callerid,s,14)
pbx.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/400-00000059”, “1?Set(CALLERID(all)=8885551212)”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/400-00000059”, “0?Set(CALLERID(all)=)”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/400-00000059”, “1?Set(CALLERID(all)=8885551212)”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/400-00000059”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:18] Set(“SIP/400-00000059”, “CDR(outbound_cnum)=8885551212”) in new stack
pbx.c: – Executing [s@macro-outbound-callerid:19] Set(“SIP/400-00000059”, “CDR(outbound_cnam)=”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/400-00000059”, “1?sub-flp-2,s,1()”) in new stack
pbx.c: – Executing [s@sub-flp-2:1] ExecIf(“SIP/400-00000059”, “0?Return()”) in new stack
pbx.c: – Executing [s@sub-flp-2:2] Return(“SIP/400-00000059”, “”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/400-00000059”, “OUTNUM=18885551212”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/400-00000059”, “custom=SIP/sip.skype.com”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/400-00000059”, “1?Set(DIAL_TRUNK_OPTIONS=M(setmusic^none)Tt)”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/400-00000059”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^none)TtM(confirm))”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:17] Macro(“SIP/400-00000059”, “dialout-trunk-predial-hook,”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/400-00000059”, “”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/400-00000059”, “0?bypass,1”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/400-00000059”, “1?Set(CONNECTEDLINE(num,i)=18885551212)”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/400-00000059”, “1?Set(CONNECTEDLINE(name,i)=CID:8885551212)”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/400-00000059”, “0?customtrunk”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“SIP/400-00000059”, “SIP/sip.skype.com/18885551212,300,M(setmusic^none)Tt”) in new stack
netsock2.c: == Using SIP RTP TOS bits 184
netsock2.c: == Using SIP RTP CoS mark 5
app_dial.c: – Called SIP/sip.skype.com/18885551212
app_dial.c: == Everyone is busy/congested at this time (1:0/0/1)
pbx.c: – Executing [s@macro-dialout-trunk:23] NoOp(“SIP/400-00000059”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 1”) in new stack
pbx.c: – Executing [s@macro-dialout-trunk:24] GotoIf(“SIP/400-00000059”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack
pbx.c: – Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
pbx.c: – Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set(“SIP/400-00000059”, “RC=1”) in new stack
pbx.c: – Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto(“SIP/400-00000059”, “1,1”) in new stack
pbx.c: – Goto (macro-dialout-trunk,1,1)
pbx.c: – Executing [1@macro-dialout-trunk:1] Goto(“SIP/400-00000059”, “continue,1”) in new stack
pbx.c: – Goto (macro-dialout-trunk,continue,1)
pbx.c: – Executing [continue@macro-dialout-trunk:1] NoOp(“SIP/400-00000059”, “TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 1 - failing through to other trunks”) in new stack
pbx.c: – Executing [continue@macro-dialout-trunk:2] Set(“SIP/400-00000059”, “CALLERID(number)=400”) in new stack
pbx.c: – Executing [18885551212@from-internal:7] Macro(“SIP/400-00000059”, “outisbusy,”) in new stack
pbx.c: – Executing [s@macro-outisbusy:1] Progress(“SIP/400-00000059”, “”) in new stack
pbx.c: – Executing [s@macro-outisbusy:2] GotoIf(“SIP/400-00000059”, “0?emergency,1”) in new stack
pbx.c: – Executing [s@macro-outisbusy:3] GotoIf(“SIP/400-00000059”, “0?intracompany,1”) in new stack
pbx.c: – Executing [s@macro-outisbusy:4] PlayTones(“SIP/400-00000059”, “congestion”) in new stack
pbx.c: – Executing [s@macro-outisbusy:5] Congestion(“SIP/400-00000059”, “20”) in new stack
app_macro.c: == Spawn extension (macro-outisbusy, s, 5) exited non-zero on ‘SIP/400-00000059’ in macro 'outisbusy’
pbx.c: == Spawn extension (from-internal, 18885551212, 7) exited non-zero on 'SIP/400-00000059’
pbx.c: – Executing [h@from-internal:1] Hangup(“SIP/400-00000059”, “”) in new stack
pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/400-00000059’

oingare · July 14, 2013, 10:51pm

Anyone- Any pointers?
If no pointers regarding my problems- where can I read more how to debug and build from source code

bksales · July 14, 2013, 11:30pm

me thinks your trunk definition leaves something to be desired

oingare · July 16, 2013, 2:21am

Thanks for the pointer- I changed it back from IP based validation to peer registration and now it initiates calls from both sides but…

I noticed my TMG firewall blocks some ports/traffic and by disabling the SIP filter- inbound calls work but outgoing is still not detecting when the call is answered. I will debug the firewall logs.
Why is the PBX box trying to open up port 25 @ IP: 98.138.112.32? I do not have any yahoo email addresses in the setup…

bksales · July 16, 2013, 11:25pm

if you have vm->email enabled.
if you want to use ip based validation instead of registration, simply add a couple of rules to the firewall to route the traffic to the pbx. I have not looked at the tmg box in a while, but it should allow you to allow traffic to/from your itsp on udp ports 5060 as well as the appropriate rtp range (generally 10001-20000).