Source IP address not in ACL

rnrstar · August 13, 2018, 9:21pm

We are running FreePBX 13.0.195.4 and we are running this in a test environment. We use Twilio for our SIP trunking. Normally we would use xxx1.pstn.us1.twilio.com for our termination URI defined in the outgoing peer details of the trunk.

This is a system we had in production but now we just want to test in our test environment so we reset the termination URI to xxx-lab.pstn.us1.twilio.com. When we try to make a call from the server to an outside number, we get the following error from Twilio.
Authentication failure - source IP Address not in ACL.
When I look at the details, it’s showing that the to: is the number I’m dialing @ xxx.ptsn.us1.twilio.com (the old termination URI) and then the from is [email protected].

Why is it showing an internal address?
Why is it using the wrong termination URI? I can’t find anywhere that it would still be defined. The trunk outgoing SIP peer details is the only place that I know it’s defined and it’s setup for the lab URI.

When I call out, I get the “all circuits are busy” message.

Any suggestions?

PitzKey · August 13, 2018, 10:06pm

Can you post a failed call log?

rnrstar · August 13, 2018, 10:15pm

[2018-08-13 15:13:40] VERBOSE[5511][C-00000082] netsock2.c: Using SIP RTP TOS bits 184
[2018-08-13 15:13:40] VERBOSE[5511][C-00000082] netsock2.c: Using SIP RTP CoS mark 5
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:1] Macro("SIP/202-00000086", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/202-00000086", "TOUCH_MONITOR=1534198420.139") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/202-00000086", "AMPUSER=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/202-00000086", "0?report") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/202-00000086", "1?Set(REALCALLERIDNUM=202)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/202-00000086", "AMPUSER=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/202-00000086", "0?limit") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/202-00000086", "AMPUSERCIDNAME=Todd G. Schacherl") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/202-00000086", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/202-00000086", "0?report") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/202-00000086", "AMPUSERCID=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/202-00000086", "__DIAL_OPTIONS=Ttr") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:12] Set("SIP/202-00000086", "CALLERID(all)="Todd G. Schacherl" &lt;202&gt;") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("SIP/202-00000086", "0?limit") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("SIP/202-00000086", "1?Set(GROUP(concurrency_limit)=202)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("SIP/202-00000086", "0?Set(CHANNEL(language)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/202-00000086", "Macro Depth is 1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/202-00000086", "1?report2:macroerror") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/202-00000086", "1?continue") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/202-00000086", "CALLERID(number)=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/202-00000086", "CALLERID(name)=Todd G. Schacherl") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("SIP/202-00000086", "0?cnum") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/202-00000086", "CDR(cnam)=Todd G. Schacherl") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/202-00000086", "CDR(cnum)=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/202-00000086", "CHANNEL(language)=en") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:2] Gosub("SIP/202-00000086", "sub-record-check,s,1(out,7025242574,dontcare)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/202-00000086", "0?initialized") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:2] Set("SIP/202-00000086", "__REC_STATUS=INITIALIZED") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:3] Set("SIP/202-00000086", "NOW=1534198420") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:4] Set("SIP/202-00000086", "__DAY=13") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:5] Set("SIP/202-00000086", "__MONTH=08") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:6] Set("SIP/202-00000086", "__YEAR=2018") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:7] Set("SIP/202-00000086", "__TIMESTR=20180813-151340") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:8] Set("SIP/202-00000086", "__FROMEXTEN=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:9] Set("SIP/202-00000086", "__MON_FMT=wav") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/202-00000086", "Recordings initialized") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/202-00000086", "0?Set(ARG3=dontcare)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:12] Set("SIP/202-00000086", "REC_POLICY_MODE_SAVE=") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/202-00000086", "0?Set(REC_STATUS=NO)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/202-00000086", "3?checkaction") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/202-00000086", "1?sub-record-check,out,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (sub-record-check,out,1)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [out@sub-record-check:1] NoOp("SIP/202-00000086", "Outbound Recording Check from 202 to 7025242574") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [out@sub-record-check:2] Set("SIP/202-00000086", "RECMODE=force") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [out@sub-record-check:3] ExecIf("SIP/202-00000086", "0?Goto(routewins)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [out@sub-record-check:4] ExecIf("SIP/202-00000086", "0?Goto(routewins)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [out@sub-record-check:5] Gosub("SIP/202-00000086", "recordcheck,1(force,out,7025242574)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/202-00000086", "Starting recording check against force") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/202-00000086", "force") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:5] Set("SIP/202-00000086", "__REC_POLICY_MODE=FORCE") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf("SIP/202-00000086", "1?startrec") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("SIP/202-00000086", "Starting recording: out, 7025242574") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:17] Set("SIP/202-00000086", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:18] Set("SIP/202-00000086", "__CALLFILENAME=out-7025242574-202-20180813-151340-1534198420.139") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:19] MixMonitor("SIP/202-00000086", "2018/08/13/out-7025242574-202-20180813-151340-1534198420.139.wav,abi(LOCAL_MIXMON_ID),") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:20] Set("SIP/202-00000086", "__MIXMON_ID=0x7f91a120ebf0") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:21] Set("SIP/202-00000086", "__RECORD_ID=SIP/202-00000086") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:22] Set("SIP/202-00000086", "__REC_STATUS=RECORDING") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:23] Set("SIP/202-00000086", "CDR(recordingfile)=out-7025242574-202-20180813-151340-1534198420.139.wav") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [recordcheck@sub-record-check:24] Return("SIP/202-00000086", "") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [out@sub-record-check:6] Return("SIP/202-00000086", "") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:3] ExecIf("SIP/202-00000086", "0 ?Set(CDR(accountcode)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:4] Set("SIP/202-00000086", "MOHCLASS=default") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:5] Set("SIP/202-00000086", "_NODEST=") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:6] Macro("SIP/202-00000086", "dialout-trunk,6,17025242574,,off") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:1] Set("SIP/202-00000086", "DIAL_TRUNK=6") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("SIP/202-00000086", "0?Set(DIAL_OPTIONS=tr)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("SIP/202-00000086", "0?sub-pincheck,s,1()") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:4] GotoIf("SIP/202-00000086", "0?disabletrunk,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:5] Set("SIP/202-00000086", "DIAL_NUMBER=17025242574") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:6] Set("SIP/202-00000086", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:7] Set("SIP/202-00000086", "OUTBOUND_GROUP=OUT_6") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:8] Set("SIP/202-00000086", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:9] GotoIf("SIP/202-00000086", "1?nomax") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-dialout-trunk,s,11)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf("SIP/202-00000086", "0?skipoutcid") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:12] Macro("SIP/202-00000086", "outbound-callerid,6") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:1] ExecIf("SIP/202-00000086", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:2] ExecIf("SIP/202-00000086", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:3] ExecIf("SIP/202-00000086", "0?Set(REALCALLERIDNUM=202)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("SIP/202-00000086", "0?Set(AMPUSER=202)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:5] GotoIf("SIP/202-00000086", "1?normcid") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-outbound-callerid,s,9)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:9] Set("SIP/202-00000086", "USEROUTCID=") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:10] Set("SIP/202-00000086", "EMERGENCYCID=") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:11] Set("SIP/202-00000086", "TRUNKOUTCID=+17029860371") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:12] GotoIf("SIP/202-00000086", "1?trunkcid") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-outbound-callerid,s,17)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:17] ExecIf("SIP/202-00000086", "1?Set(CALLERID(all)=+17029860371)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:18] ExecIf("SIP/202-00000086", "0?Set(CALLERID(all)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:19] ExecIf("SIP/202-00000086", "0?Set(CALLERID(all)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:20] ExecIf("SIP/202-00000086", "0?Set(CALLERID(all)=)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf("SIP/202-00000086", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("SIP/202-00000086", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:23] Set("SIP/202-00000086", "CDR(outbound_cnum)=+17029860371") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outbound-callerid:24] Set("SIP/202-00000086", "CDR(outbound_cnam)=") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:13] GosubIf("SIP/202-00000086", "1?sub-flp-6,s,1()") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@sub-flp-6:1] ExecIf("SIP/202-00000086", "1?Return()") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:14] Set("SIP/202-00000086", "OUTNUM=+17025242574") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:15] Set("SIP/202-00000086", "custom=SIP/TwilioSIP") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:16] ExecIf("SIP/202-00000086", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("SIP/202-00000086", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:18] Macro("SIP/202-00000086", "dialout-trunk-predial-hook,") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/202-00000086", "") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:19] GotoIf("SIP/202-00000086", "0?skipcrm") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:20] Set("SIP/202-00000086", "__CRM_DIRECTION=OUTBOUND") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:21] Set("SIP/202-00000086", "__CRM_DESTINATION=+17025242574") in new stack
[2018-08-13 15:13:40] VERBOSE[28682][C-00000082] app_mixmonitor.c: Begin MixMonitor Recording SIP/202-00000086
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:22] Set("SIP/202-00000086", "__CRM_SOURCE=202") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:23] AGI("SIP/202-00000086", "sangomacrm.agi") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] res_agi.c: &lt;SIP/202-00000086&gt;AGI Script sangomacrm.agi completed, returning 0
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:24] Set("SIP/202-00000086", "CHANNEL(hangup_handler_push)=crm-hangup,s,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:25] NoOp("SIP/202-00000086", "CRM Finished") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:26] GotoIf("SIP/202-00000086", "0?bypass,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:27] ExecIf("SIP/202-00000086", "1?Set(CONNECTEDLINE(num,i)=17025242574)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:28] ExecIf("SIP/202-00000086", "1?Set(CONNECTEDLINE(name,i)=CID:+17029860371)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf("SIP/202-00000086", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+17029860371)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:30] GotoIf("SIP/202-00000086", "0?customtrunk") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:31] Dial("SIP/202-00000086", "SIP/TwilioSIP/+17025242574,300,Tt") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] netsock2.c: Using SIP RTP TOS bits 184
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] netsock2.c: Using SIP RTP CoS mark 5
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] app_dial.c: Called SIP/TwilioSIP/+17025242574
[2018-08-13 15:13:40] WARNING[5511][C-00000082] chan_sip.c: Received response: "Forbidden" from '&lt;sip:[email protected]&gt;;tag=as3cec8aeb'
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:32] NoOp("SIP/202-00000086", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 21") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-dialout-trunk:33] GotoIf("SIP/202-00000086", "0?continue,1:s-CHANUNAVAIL,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("SIP/202-00000086", "RC=21") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("SIP/202-00000086", "21,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-dialout-trunk,21,1)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [21@macro-dialout-trunk:1] Goto("SIP/202-00000086", "continue,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [continue@macro-dialout-trunk:1] NoOp("SIP/202-00000086", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 21 - failing through to other trunks") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [continue@macro-dialout-trunk:2] ExecIf("SIP/202-00000086", "1?Set(CALLERID(number)=202)") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [7025242574@from-internal:7] Macro("SIP/202-00000086", "outisbusy,") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outisbusy:1] Progress("SIP/202-00000086", "") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outisbusy:2] GotoIf("SIP/202-00000086", "0?emergency,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outisbusy:3] GotoIf("SIP/202-00000086", "0?intracompany,1") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-outisbusy:4] Playback("SIP/202-00000086", "all-circuits-busy-now&amp;please-try-call-later, noanswer") in new stack
[2018-08-13 15:13:40] VERBOSE[28675][C-00000082] file.c: &lt;SIP/202-00000086&gt; Playing 'all-circuits-busy-now.ulaw' (language 'en')
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] file.c: &lt;SIP/202-00000086&gt; Playing 'please-try-call-later.ulaw' (language 'en')
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [h@from-internal:1] Macro("SIP/202-00000086", "hangupcall") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/202-00000086", "1?theend") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/202-00000086", "0?Set(CDR(recordingfile)=)") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/202-00000086", "") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/202-00000086' in macro 'hangupcall'
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/202-00000086'
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] app_stack.c: SIP/202-00000086 Internal Gosub(crm-hangup,s,1) start
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:1] NoOp("SIP/202-00000086", "Sending Hangup to CRM") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:2] NoOp("SIP/202-00000086", "HANGUP CAUSE: 21") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:3] ExecIf("SIP/202-00000086", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:4] NoOp("SIP/202-00000086", "MASTER CHANNEL: 1534198420.139 = 1534198420.139") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:5] GotoIf("SIP/202-00000086", "0?return") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:6] Set("SIP/202-00000086", "__CRM_HANGUP=1") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:7] AGI("SIP/202-00000086", "sangomacrm.agi") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] res_agi.c: &lt;SIP/202-00000086&gt;AGI Script sangomacrm.agi completed, returning 0
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] pbx.c: Executing [s@crm-hangup:8] Return("SIP/202-00000086", "") in new stack
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/202-00000086'
[2018-08-13 15:13:42] VERBOSE[28675][C-00000082] app_stack.c: SIP/202-00000086 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-08-13 15:13:42] VERBOSE[28682][C-00000082] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-08-13 15:13:42] VERBOSE[28682][C-00000082] app_mixmonitor.c: End MixMonitor Recording SIP/202-00000086

dicko · August 13, 2018, 10:23pm

[2018-08-13 15:13:40] WARNING[5511][C-00000082] chan_sip.c: Received response: “Forbidden” from ‘<sip:[email protected]>;tag=as3cec8aeb’

apparently you can’t send calls through 206.198.135.252

rnrstar · August 13, 2018, 10:26pm

RIght, I get that. It’s trying to send to cfusa-cc.pstn.us1.twilio.com when it should be sending to cclab.ptsn.us1.twilio.com. What I don’t get is why it’s still referencing cfusa-cc when it says cclab in the outbound peer settings for the Twilio trunk.

IOW, cfusa-cc has whitelisted our .250 addr and cclab has .252 whitelisted. Why is it trying to hit cfusa-cc instead of cclab?

dicko · August 13, 2018, 10:28pm

possibly its in /etc/hosts, possibly your DNS server is not truly functional, Use the raw IP instead.

but, significantly , from my machines

ping cclab.ptsn.us1.twilio.com
ping: unknown host cclab.ptsn.us1.twilio.com

rnrstar · August 13, 2018, 10:39pm

We did an fwconsole restart and that seems to have taken care of this particular issue. Not sure why that would make any difference if we applied the changes. Thanks for the suggestions.

dicko · August 13, 2018, 11:00pm

Consider it a birthday present.

cynjut · August 14, 2018, 2:13pm

Since most DNS servers will provide addresses in a round-robin (if there’s more than one address for that name), then you restart the server, the SIP connections get the right IP address. As it turns out, you got one that works with your config. if the problem comes back, it will be because of a different IP address getting assigned.

system · August 14, 2019, 2:13pm

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.