Trunk "No Response" or "404" Timeout Settings

xptpa2020 · September 2, 2015, 4:11pm

Hello,

I have set up a test FreePBX with the first two trunks with SIP provider Alpha simulating a “failed” state and the third trunk with SIP provider Beta is still active. They’re actually pointing to a host that doesn’t exist, but that could also occur if our SIP provider’s SIP switch or the ISPs to their equipment were down, their datacenter, etc.

My scenario is this:

I have two trunks with SIP provider Alpha - one is primary, the other is secondary. I then have a third trunk out SIP provider Beta which I use if carrier Alpha were to go down entirely. I noticed that when FreePBX attempts to send the call to the first trunk, then the next, and the last, each trunk would take 30 seconds to timeout when no response is received prior to going out the last trunk.

I have investigated the cause of this issue and found the trunk timeout option in Advanced Settings can lower this timeout, but that is also a timeout even if nobody picks up after the trunk is actually connected and ringing.

I have attached a log file that details my scenario. I am trying to find out if there is a way to lower the trunk “no response” timeout (as in, the trunk doesn’t send us a 408, a 503, and is instead a 404 or “not found”). I do not want to lower the timeout that would be used when users hear a ringing sound - I simply want to lower the timeout before a given trunk is deemed unavailable by FreePBX.

The reason this is even an issue to me is if carrier Alpha were to go down, users would have to wait beyond 60 seconds of silence on their phone before the call would actually connect out carrier Beta. Almost all of our users would give up somewhere around 30 seconds of silence before they wait and hear it connect 30 seconds later.

My question: Is it possible to have the first two trunks attempted simultaneously, or is it possible that I can lower the “no response” timeout value without affecting the “ringing, no response” timeout value?

Any help or advice is appreciated. I’d be glad to share my findings after adjusting anything on my end.

Thank you,

Jon

xptpa2020 · September 2, 2015, 4:11pm

Here’s my log file:

[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-user-callerid:31] Set("SIP/100-00000418", "CALLERID(name)=John Smith") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-user-callerid:32] Set("SIP/100-00000418", "CDR(cnum)=115") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-user-callerid:33] Set("SIP/100-00000418", "CDR(cnam)=John Smith") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-user-callerid:34] Set("SIP/100-00000418", "CHANNEL(language)=en") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:2] Gosub("SIP/100-00000418", "sub-record-check,s,1(out,7775554422,dontcare)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:1] GotoIf("SIP/100-00000418", "0?initialized") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:2] Set("SIP/100-00000418", "__REC_STATUS=INITIALIZED") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:3] Set("SIP/100-00000418", "NOW=1441208197") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:4] Set("SIP/100-00000418", "__DAY=02") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:5] Set("SIP/100-00000418", "__MONTH=09") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:6] Set("SIP/100-00000418", "__YEAR=2015") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:7] Set("SIP/100-00000418", "__TIMESTR=20150902-113637") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:8] Set("SIP/100-00000418", "__FROMEXTEN=115") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:9] Set("SIP/100-00000418", "__MON_FMT=wav") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:10] NoOp("SIP/100-00000418", "Recordings initialized") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:11] ExecIf("SIP/100-00000418", "0?Set(ARG3=dontcare)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:12] Set("SIP/100-00000418", "REC_POLICY_MODE_SAVE=") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:13] ExecIf("SIP/100-00000418", "0?Set(REC_STATUS=NO)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:14] GotoIf("SIP/100-00000418", "3?checkaction") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (sub-record-check,s,17)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-record-check:17] GotoIf("SIP/100-00000418", "1?sub-record-check,out,1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (sub-record-check,out,1)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [out@sub-record-check:1] NoOp("SIP/100-00000418", "Outbound Recording Check from 115 to 7775554422") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [out@sub-record-check:2] Set("SIP/100-00000418", "RECMODE=dontcare") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [out@sub-record-check:3] ExecIf("SIP/100-00000418", "1?Goto(routewins)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (sub-record-check,out,7)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [out@sub-record-check:7] Gosub("SIP/100-00000418", "recordcheck,1(dontcare,out,7775554422)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/100-00000418", "Starting recording check against dontcare") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [recordcheck@sub-record-check:2] Goto("SIP/100-00000418", "dontcare") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (sub-record-check,recordcheck,3)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [recordcheck@sub-record-check:3] Return("SIP/100-00000418", "") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [out@sub-record-check:8] Return("SIP/100-00000418", "") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:3] ExecIf("SIP/100-00000418", "0 ?Set(CDR(accountcode)=)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:4] Set("SIP/100-00000418", "MOHCLASS=default") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:5] Set("SIP/100-00000418", "_NODEST=") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:6] Macro("SIP/100-00000418", "dialout-trunk,8,7775554422,,on") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/100-00000418", "DIAL_TRUNK=8") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/100-00000418", "0?sub-pincheck,s,1()") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/100-00000418", "1?disabletrunk,1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-dialout-trunk,disabletrunk,1)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [disabletrunk@macro-dialout-trunk:1] NoOp("SIP/100-00000418", "TRUNK: AMP:Local/$OUTNUM$@ext-did DISABLED - falling through to next trunk") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:7] Macro("SIP/100-00000418", "dialout-trunk,1,7775554422,,on") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/100-00000418", "DIAL_TRUNK=1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/100-00000418", "0?sub-pincheck,s,1()") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/100-00000418", "0?disabletrunk,1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/100-00000418", "DIAL_NUMBER=7775554422") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/100-00000418", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/100-00000418", "OUTBOUND_GROUP=OUT_1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/100-00000418", "1?nomax") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/100-00000418", "0?skipoutcid") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/100-00000418", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/100-00000418", "outbound-callerid,1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/100-00000418", "0?Set(CALLERPRES()=)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/100-00000418", "0?Set(REALCALLERIDNUM=115)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/100-00000418", "1?normcid") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/100-00000418", "USEROUTCID=<5554442222>") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/100-00000418", "EMERGENCYCID=") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/100-00000418", "TRUNKOUTCID=") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/100-00000418", "1?trunkcid") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-outbound-callerid,s,14)
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/100-00000418", "0?Set(CALLERID(all)=)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/100-00000418", "1?Set(CALLERID(all)=<5554442222>)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/100-00000418", "0?Set(CALLERID(all)=)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/100-00000418", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:18] Set("SIP/100-00000418", "CDR(outbound_cnum)=5554442222") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:19] Set("SIP/100-00000418", "CDR(outbound_cnam)=") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/100-00000418", "0?sub-flp-1,s,1()") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/100-00000418", "OUTNUM=7775554422") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/100-00000418", "custom=SIP/ICE") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/100-00000418", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/100-00000418", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/100-00000418", "dialout-trunk-predial-hook,") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/100-00000418", "") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/100-00000418", "0?bypass,1") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/100-00000418", "1?Set(CONNECTEDLINE(num,i)=7775554422)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/100-00000418", "1?Set(CONNECTEDLINE(name,i)=CID:5554442222)") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/100-00000418", "0?customtrunk") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Dial("SIP/100-00000418", "SIP/ICE/7775554422,300,Tt") in new stack
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP RTP TOS bits 184
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP RTP CoS mark 5
[2015-09-02 11:36:37] VERBOSE[8928][C-00000eee] app_dial.c:     -- Called SIP/ICE/7775554422
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] app_dial.c:   == Everyone is busy/congested at this time (1:0/0/1)
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/100-00000418", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 18") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/100-00000418", "1?continue,1:s-CHANUNAVAIL,1") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-dialout-trunk,continue,1)
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [continue@macro-dialout-trunk:1] NoOp("SIP/100-00000418", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 18 - failing through to other trunks") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [continue@macro-dialout-trunk:2] Set("SIP/100-00000418", "CALLERID(number)=115") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:8] Macro("SIP/100-00000418", "dialout-trunk,3,7775554422,,on") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/100-00000418", "DIAL_TRUNK=3") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/100-00000418", "0?sub-pincheck,s,1()") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/100-00000418", "0?disabletrunk,1") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/100-00000418", "DIAL_NUMBER=7775554422") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/100-00000418", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/100-00000418", "OUTBOUND_GROUP=OUT_3") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/100-00000418", "0?nomax") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/100-00000418", "0?chanfull") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/100-00000418", "0?skipoutcid") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/100-00000418", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/100-00000418", "outbound-callerid,3") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/100-00000418", "0?Set(CALLERPRES()=)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/100-00000418", "0?Set(REALCALLERIDNUM=115)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/100-00000418", "1?normcid") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/100-00000418", "USEROUTCID=<5554442222>") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/100-00000418", "EMERGENCYCID=") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/100-00000418", "TRUNKOUTCID=") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/100-00000418", "1?trunkcid") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-outbound-callerid,s,14)
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/100-00000418", "0?Set(CALLERID(all)=)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/100-00000418", "1?Set(CALLERID(all)=<5554442222>)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/100-00000418", "0?Set(CALLERID(all)=)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/100-00000418", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:18] Set("SIP/100-00000418", "CDR(outbound_cnum)=5554442222") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:19] Set("SIP/100-00000418", "CDR(outbound_cnam)=") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/100-00000418", "0?sub-flp-3,s,1()") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/100-00000418", "OUTNUM=7775554422") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/100-00000418", "custom=SIP/ICE-International") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/100-00000418", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/100-00000418", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/100-00000418", "dialout-trunk-predial-hook,") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/100-00000418", "") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/100-00000418", "0?bypass,1") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/100-00000418", "1?Set(CONNECTEDLINE(num,i)=7775554422)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/100-00000418", "1?Set(CONNECTEDLINE(name,i)=CID:5554442222)") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/100-00000418", "0?customtrunk") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Dial("SIP/100-00000418", "SIP/ICE-International/7775554422,300,Tt") in new stack
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP RTP TOS bits 184
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP RTP CoS mark 5
[2015-09-02 11:37:09] VERBOSE[8928][C-00000eee] app_dial.c:     -- Called SIP/ICE-International/7775554422
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] app_dial.c:     -- SIP/ICE-International-0000041a is circuit-busy
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] app_dial.c:   == Everyone is busy/congested at this time (1:0/1/0)
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/100-00000418", "Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 18") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/100-00000418", "1?continue,1:s-CONGESTION,1") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-dialout-trunk,continue,1)
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [continue@macro-dialout-trunk:1] NoOp("SIP/100-00000418", "TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 18 - failing through to other trunks") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [continue@macro-dialout-trunk:2] Set("SIP/100-00000418", "CALLERID(number)=115") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [7775554422@from-internal:9] Macro("SIP/100-00000418", "dialout-trunk,7,7775554422,,off") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/100-00000418", "DIAL_TRUNK=7") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/100-00000418", "0?sub-pincheck,s,1()") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/100-00000418", "0?disabletrunk,1") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/100-00000418", "DIAL_NUMBER=7775554422") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/100-00000418", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/100-00000418", "OUTBOUND_GROUP=OUT_7") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/100-00000418", "1?nomax") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/100-00000418", "0?skipoutcid") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/100-00000418", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/100-00000418", "outbound-callerid,7") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/100-00000418", "0?Set(CALLERPRES()=)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/100-00000418", "0?Set(REALCALLERIDNUM=115)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/100-00000418", "1?normcid") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/100-00000418", "USEROUTCID=<5554442222>") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/100-00000418", "EMERGENCYCID=") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/100-00000418", "TRUNKOUTCID=") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/100-00000418", "1?trunkcid") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-outbound-callerid,s,14)
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/100-00000418", "0?Set(CALLERID(all)=)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/100-00000418", "1?Set(CALLERID(all)=<5554442222>)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/100-00000418", "0?Set(CALLERID(all)=)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/100-00000418", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:18] Set("SIP/100-00000418", "CDR(outbound_cnum)=5554442222") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-outbound-callerid:19] Set("SIP/100-00000418", "CDR(outbound_cnam)=") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/100-00000418", "1?sub-flp-7,s,1()") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-flp-7:1] ExecIf("SIP/100-00000418", "0?Set(TARGET_FLP_7=AUTHCODE*7775554422)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-flp-7:2] GotoIf("SIP/100-00000418", "0?match") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-flp-7:3] ExecIf("SIP/100-00000418", "1?Set(TARGET_FLP_7=AUTHCODE*17775554422)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-flp-7:4] GotoIf("SIP/100-00000418", "1?match") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (sub-flp-7,s,8)
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-flp-7:8] Set("SIP/100-00000418", "DIAL_NUMBER=AUTHCODE*17775554422") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@sub-flp-7:9] Return("SIP/100-00000418", "") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/100-00000418", "OUTNUM=AUTHCODE*17775554422") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/100-00000418", "custom=SIP/ICE-FR") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/100-00000418", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/100-00000418", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/100-00000418", "dialout-trunk-predial-hook,") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/100-00000418", "") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/100-00000418", "0?bypass,1") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/100-00000418", "1?Set(CONNECTEDLINE(num,i)=AUTHCODE*17775554422)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/100-00000418", "1?Set(CONNECTEDLINE(name,i)=CID:5554442222)") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/100-00000418", "0?customtrunk") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Dial("SIP/100-00000418", "SIP/ICE-FR/AUTHCODE*17775554422,300,Tt") in new stack
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP VIDEO TOS bits 136
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP VIDEO CoS mark 6
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP RTP TOS bits 184
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] netsock2.c:   == Using SIP RTP CoS mark 5
[2015-09-02 11:37:41] VERBOSE[8928][C-00000eee] app_dial.c:     -- Called SIP/ICE-FR/AUTHCODE*17775554422
[2015-09-02 11:37:43] VERBOSE[8928][C-00000eee] app_dial.c:     -- SIP/ICE-FR-0000041b is making progress passing it to SIP/100-00000418
[2015-09-02 11:37:49] VERBOSE[8928][C-00000eee] app_dial.c:     -- SIP/ICE-FR-0000041b answered SIP/100-00000418
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [h@macro-dialout-trunk:1] Macro("SIP/100-00000418", "hangupcall,") in new stack
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-hangupcall:1] ExecIf("SIP/100-00000418", "0?Set(CDR(recordingfile)=.wav)") in new stack
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-hangupcall:2] GotoIf("SIP/100-00000418", "1?theend") in new stack
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:     -- Goto (macro-hangupcall,s,4)
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:     -- Executing [s@macro-hangupcall:4] Hangup("SIP/100-00000418", "") in new stack
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] app_macro.c:   == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/100-00000418' in macro 'hangupcall'
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:   == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/100-00000418'
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/100-00000418' in macro 'dialout-trunk'
[2015-09-02 11:37:52] VERBOSE[8928][C-00000eee] pbx.c:   == Spawn extension (from-internal, 7775554422, 9) exited non-zero on 'SIP/100-00000418'