Rerouting outbound calls via foreign PBX - incorrect destination problem

I have a confusing problem where calls that should terminate with a circuit busy on a local PBX (PBX-A), instead they are being dropped onto an ivr (ivr-2) on the partner PBX (PBX-B).

The logic is that a call made from PBX-A has an outbound route to first attempt to use “DAHDi g0” on PBX-A with a specific CID. If that trunk is busy, the route will failover to trunk “IAX internal” on PBX-A which passes the call to PBX-B via an IAX trunk. PBX-B has an inbound route with the same specific CID that will identify the calling CID and pass it to trunk “DAHDi g0” on PBX-B. If PBX-B “DAHDi g0” trunk is busy, the call should then return control to PBX-A with a cicuit busy causing PBX-A to continue to the next trunk in the outbound route.

What is actually happening -
a call made from PBX-A uses outbound route to “DAHDi g0” on PBX-A with a specific CID. That trunk is busy (expected), the route then failovers to trunk “IAX internal” and passes the call to PBX-B via an IAX trunk. PBX-B passes it to trunk “DAHDi g0” on PBX-B. PBX-B “DAHDi g0” trunk is busy (also expected), the call is then dropped onto PBX-B’s IVR-2 every time (regardless of the time - see next paragraph for explanation).

I have not made any dialplan logic that would direct any calls to the IVR-2 apart from a time condition which is set to use IVR-1 for the majority of the time and IVR-2 when closed. FYI - The time condition is currently set to ‘open’ thus IVR-1 should be the termination point if the inbound route is working correctly on PBX-B.

I have included the output from PBX-A and PBX-B for the duration of the attempted call at the end of the post.

If anyone can direct me to where to find the point at which the decision is made on PBX-B to pass the call to the IVR instead of giving a curcuit busy signal and terminating the call so that PBX-A can continue the route failover trunk attempts.

Systems:
FreePBX 2.11.0.10 (FPBX ISO release)
Asterisk 11.4.0
Centos 6.4
DAHDi 2.7.0
(All modules loaded and all are updated as of 12/09/2013)

Hardware:
PBX-A: 2x Digium AEX440PELF w/ 3x FXO & 1x FXS
PBX-B: Digium TE133F (Single Span e1) & Digium AEX440PELF w/ 3x FXO & 1x FXS

Setup:
2 geographically seperated locations connected with VPN.
3x Analogue lines at each location for capped calling (free).
1x 10 digital line PRI e1 connection at one location.
IAX trunk using from-internal context for interPBX calls and xfers - tested and working internally.

Trunks:
DAHDi g0 - round robin for 3x capped price analogue lines.
IAX2 internal - send calls to partner PBX for rerouting to partner DAHDi g0.
DAHDi g1 - round robin for non capped digital and analogue lines.

PBX-A’s call logging:
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:1] Macro(“SIP/402-0000002c”, “user-callerid,LIMIT,”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/402-0000002c”, “TOUCH_MONITOR=1379026429.82”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/402-0000002c”, “AMPUSER=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/402-0000002c”, “0?report”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/402-0000002c”, “1?Set(REALCALLERIDNUM=402)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/402-0000002c”, “AMPUSER=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:6] Set(“SIP/402-0000002c”, “AMPUSERCIDNAME=Shane Gates”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:7] GotoIf(“SIP/402-0000002c”, “0?report”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:8] Set(“SIP/402-0000002c”, “AMPUSERCID=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:9] Set(“SIP/402-0000002c”, “__DIAL_OPTIONS=Ttr”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:10] Set(“SIP/402-0000002c”, “CALLERID(all)=“Shane Gates” <402>”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/402-0000002c”, “0?limit”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:12] ExecIf(“SIP/402-0000002c”, “1?Set(GROUP(concurrency_limit)=402)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:13] ExecIf(“SIP/402-0000002c”, “0?Set(CHANNEL(language)=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:14] GosubIf(“SIP/402-0000002c”, “7?sub-ccss,s,1(from-internal,33333333)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-ccss:1] ExecIf(“SIP/402-0000002c”, “0?Return()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-ccss:2] Set(“SIP/402-0000002c”, “CCSS_SETUP=TRUE”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-ccss:3] GosubIf(“SIP/402-0000002c”, “0?monitor_config,1(from-internal,33333333):monitor_default,1(from-internal,33333333)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/402-0000002c”, “0?is_exten”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [monitor_default@sub-ccss:2] StackPop(“SIP/402-0000002c”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [monitor_default@sub-ccss:3] Return(“SIP/402-0000002c”, “FALSE”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/402-0000002c”, “1?continue”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-user-callerid,s,28)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/402-0000002c”, “CALLERID(number)=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/402-0000002c”, “CALLERID(name)=Shane Gates”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/402-0000002c”, “CDR(cnum)=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/402-0000002c”, “CDR(cnam)=Shane Gates”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/402-0000002c”, “CHANNEL(language)=en”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:2] Set(“SIP/402-0000002c”, “MOHCLASS=default”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:3] ExecIf(“SIP/402-0000002c”, “1?Set(TRUNKCIDOVERRIDE=0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:4] Set(“SIP/402-0000002c”, “_NODEST=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:5] Gosub(“SIP/402-0000002c”, “sub-record-check,s,1(out,33333333,)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:1] Set(“SIP/402-0000002c”, “REC_POLICY_MODE_SAVE=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:2] GotoIf(“SIP/402-0000002c”, “1?check”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (sub-record-check,s,7)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:7] Set(“SIP/402-0000002c”, “__MON_FMT=wav”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:8] GotoIf(“SIP/402-0000002c”, “1?next”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (sub-record-check,s,11)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:11] ExecIf(“SIP/402-0000002c”, “0?Return()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:12] ExecIf(“SIP/402-0000002c”, “0?Set(__REC_POLICY_MODE=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:13] GotoIf(“SIP/402-0000002c”, “0?out,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/402-0000002c”, “__REC_STATUS=INITIALIZED”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/402-0000002c”, “NOW=1379026429”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/402-0000002c”, “__DAY=13”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/402-0000002c”, “__MONTH=09”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/402-0000002c”, “__YEAR=2013”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/402-0000002c”, “__TIMESTR=20130913-085349”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/402-0000002c”, “__FROMEXTEN=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:21] Set(“SIP/402-0000002c”, “__CALLFILENAME=out-33333333-402-20130913-085349-1379026429.82”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-record-check:22] Goto(“SIP/402-0000002c”, “out,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (sub-record-check,out,1)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [out@sub-record-check:1] ExecIf(“SIP/402-0000002c”, “1?Set(__REC_POLICY_MODE=dontcare)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [out@sub-record-check:2] GosubIf(“SIP/402-0000002c”, “0?record,1(exten,33333333,402)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [out@sub-record-check:3] Return(“SIP/402-0000002c”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:6] Macro(“SIP/402-0000002c”, “dialout-trunk,1,33333333,on”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/402-0000002c”, “DIAL_TRUNK=1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/402-0000002c”, “0?sub-pincheck,s,1()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/402-0000002c”, “0?disabletrunk,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/402-0000002c”, “DIAL_NUMBER=33333333”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/402-0000002c”, “DIAL_TRUNK_OPTIONS=Ttr”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/402-0000002c”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/402-0000002c”, “0?nomax”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:8] GotoIf(“SIP/402-0000002c”, “0?chanfull”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/402-0000002c”, “0?skipoutcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/402-0000002c”, “DIAL_TRUNK_OPTIONS=Tt”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/402-0000002c”, “outbound-callerid,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERPRES()=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/402-0000002c”, “0?Set(REALCALLERIDNUM=402)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/402-0000002c”, “1?normcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-outbound-callerid,s,6)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/402-0000002c”, “USEROUTCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/402-0000002c”, “EMERGENCYCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/402-0000002c”, “TRUNKOUTCID=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/402-0000002c”, “1?trunkcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-outbound-callerid,s,14)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/402-0000002c”, “1?Set(CALLERID(all)=0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERID(all)=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/402-0000002c”, “1?Set(CALLERID(all)=0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:18] Set(“SIP/402-0000002c”, “CDR(outbound_cnum)=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:19] Set(“SIP/402-0000002c”, “CDR(outbound_cnam)=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/402-0000002c”, “1?sub-flp-1,s,1()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@sub-flp-1:1] ExecIf(“SIP/402-0000002c”, “1?Return()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/402-0000002c”, “OUTNUM=33333333”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/402-0000002c”, “custom=DAHDI/g0”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/402-0000002c”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/402-0000002c”, “0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:17] Macro(“SIP/402-0000002c”, “dialout-trunk-predial-hook,”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/402-0000002c”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/402-0000002c”, “0?bypass,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/402-0000002c”, “1?Set(CONNECTEDLINE(num,i)=33333333)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/402-0000002c”, “1?Set(CONNECTEDLINE(name,i)=CID:0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/402-0000002c”, “0?customtrunk”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“SIP/402-0000002c”, “DAHDI/g0/33333333,300,Tt”) in new stack
[2013-09-13 08:53:49] WARNING[16206][C-0000002c] app_dial.c: Unable to create channel of type ‘DAHDI’ (cause 34 - Circuit/channel congestion)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] app_dial.c: == Everyone is busy/congested at this time (1:0/1/0)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:23] NoOp(“SIP/402-0000002c”, “Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 34”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:24] GotoIf(“SIP/402-0000002c”, “1?continue,1:s-CONGESTION,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-dialout-trunk,continue,1)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [continue@macro-dialout-trunk:1] NoOp(“SIP/402-0000002c”, “TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 34 - failing through to other trunks”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [continue@macro-dialout-trunk:2] Set(“SIP/402-0000002c”, “CALLERID(number)=402”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [33333333@from-internal:7] Macro(“SIP/402-0000002c”, “dialout-trunk,2,33333333,off”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/402-0000002c”, “DIAL_TRUNK=2”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/402-0000002c”, “0?sub-pincheck,s,1()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/402-0000002c”, “0?disabletrunk,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/402-0000002c”, “DIAL_NUMBER=33333333”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/402-0000002c”, “DIAL_TRUNK_OPTIONS=Ttr”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/402-0000002c”, “OUTBOUND_GROUP=OUT_2”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/402-0000002c”, “1?nomax”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-dialout-trunk,s,9)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/402-0000002c”, “0?skipoutcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/402-0000002c”, “DIAL_TRUNK_OPTIONS=Tt”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/402-0000002c”, “outbound-callerid,2”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERPRES()=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/402-0000002c”, “0?Set(REALCALLERIDNUM=402)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/402-0000002c”, “1?normcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-outbound-callerid,s,6)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/402-0000002c”, “USEROUTCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/402-0000002c”, “EMERGENCYCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/402-0000002c”, “TRUNKOUTCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/402-0000002c”, “1?trunkcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-outbound-callerid,s,14)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERID(all)=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERID(all)=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/402-0000002c”, “1?Set(CALLERID(all)=0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/402-0000002c”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:18] Set(“SIP/402-0000002c”, “CDR(outbound_cnum)=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-outbound-callerid:19] Set(“SIP/402-0000002c”, “CDR(outbound_cnam)=”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/402-0000002c”, “0?sub-flp-2,s,1()”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/402-0000002c”, “OUTNUM=33333333”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/402-0000002c”, “custom=IAX2/IAX-Brendale”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/402-0000002c”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/402-0000002c”, “0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:17] Macro(“SIP/402-0000002c”, “dialout-trunk-predial-hook,”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/402-0000002c”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/402-0000002c”, “0?bypass,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/402-0000002c”, “1?Set(CONNECTEDLINE(num,i)=33333333)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/402-0000002c”, “1?Set(CONNECTEDLINE(name,i)=CID:0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/402-0000002c”, “0?customtrunk”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“SIP/402-0000002c”, “IAX2/IAX-Brendale/33333333,300,Tt”) in new stack
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] app_dial.c: – Called IAX2/IAX-Brendale/33333333
[2013-09-13 08:53:49] VERBOSE[3059][C-0000002c] chan_iax2.c: – Call accepted by 10.1.1.200 (format gsm)
[2013-09-13 08:53:49] VERBOSE[3059][C-0000002c] chan_iax2.c: – Format for call is (gsm)
[2013-09-13 08:53:49] VERBOSE[16206][C-0000002c] app_dial.c: – IAX2/IAX-Brendale-3140 answered SIP/402-0000002c
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/402-0000002c”, “hangupcall,”) in new stack
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/402-0000002c”, “1?theend”) in new stack
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: – Goto (macro-hangupcall,s,3)
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“SIP/402-0000002c”, “0?Set(CDR(recordingfile)=)”) in new stack
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“SIP/402-0000002c”, “”) in new stack
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/402-0000002c’ in macro ‘hangupcall’
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on ‘SIP/402-0000002c’
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] chan_iax2.c: – Hungup ‘IAX2/IAX-Brendale-3140’
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] app_macro.c: == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on ‘SIP/402-0000002c’ in macro ‘dialout-trunk’
[2013-09-13 08:53:52] VERBOSE[16206][C-0000002c] pbx.c: == Spawn extension (from-internal, 33333333, 7) exited non-zero on ‘SIP/402-0000002c’

PBX-B’s call logging:
[2013-09-13 08:53:29] VERBOSE[22800][C-00000027] pbx.c: – Executing [s@ivr-2:6] Wait(“IAX2/IAX-Redcliffe-5285”, “1”) in new stack
[2013-09-13 08:53:30] VERBOSE[22800][C-00000027] pbx.c: – Executing [s@ivr-2:7] Set(“IAX2/IAX-Redcliffe-5285”, “IVR_MSG=custom/Closed”) in new stack
[2013-09-13 08:53:30] VERBOSE[22800][C-00000027] pbx.c: – Executing [s@ivr-2:8] Set(“IAX2/IAX-Redcliffe-5285”, “TIMEOUT(digit)=3”) in new stack
[2013-09-13 08:53:30] VERBOSE[22800][C-00000027] func_timeout.c: – Digit timeout set to 3.000
[2013-09-13 08:53:30] VERBOSE[22800][C-00000027] pbx.c: – Executing [s@ivr-2:9] ExecIf(“IAX2/IAX-Redcliffe-5285”, “1?Background(custom/Closed)”) in new stack
[2013-09-13 08:53:30] VERBOSE[22800][C-00000027] file.c: – <IAX2/IAX-Redcliffe-5285> Playing ‘custom/Closed.slin’ (language ‘en’)
[2013-09-13 08:53:33] VERBOSE[22800][C-00000027] pbx.c: == Spawn extension (ivr-2, s, 9) exited non-zero on ‘IAX2/IAX-Redcliffe-5285’
[2013-09-13 08:53:33] VERBOSE[22800][C-00000027] pbx.c: – Executing [h@ivr-2:1] Hangup(“IAX2/IAX-Redcliffe-5285”, “”) in new stack
[2013-09-13 08:53:33] VERBOSE[22800][C-00000027] pbx.c: == Spawn extension (ivr-2, h, 1) exited non-zero on ‘IAX2/IAX-Redcliffe-5285’
[2013-09-13 08:53:33] VERBOSE[22800][C-00000027] chan_iax2.c: – Hungup ‘IAX2/IAX-Redcliffe-5285’
[2013-09-13 08:53:49] VERBOSE[2101] chan_iax2.c: – Accepting UNAUTHENTICATED call from 192.168.0.200:
> requested format = alaw,
> requested prefs = (alaw|gsm|g729),
> actual format = gsm,
> host prefs = (gsm|g729|alaw),
> priority = mine
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:1] Macro(“IAX2/IAX-Redcliffe-2314”, “user-callerid,LIMIT,”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:1] Set(“IAX2/IAX-Redcliffe-2314”, “TOUCH_MONITOR=1379026429.47”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:2] Set(“IAX2/IAX-Redcliffe-2314”, “AMPUSER=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?report”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Set(REALCALLERIDNUM=0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:5] Set(“IAX2/IAX-Redcliffe-2314”, “AMPUSER=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:6] Set(“IAX2/IAX-Redcliffe-2314”, “AMPUSERCIDNAME=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:7] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?report”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (macro-user-callerid,s,15)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?continue”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (macro-user-callerid,s,28)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:28] Set(“IAX2/IAX-Redcliffe-2314”, “CALLERID(number)=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:29] Set(“IAX2/IAX-Redcliffe-2314”, “CALLERID(name)=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:30] Set(“IAX2/IAX-Redcliffe-2314”, “CDR(cnum)=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:31] Set(“IAX2/IAX-Redcliffe-2314”, “CDR(cnam)=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-user-callerid:32] Set(“IAX2/IAX-Redcliffe-2314”, “CHANNEL(language)=en”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:2] Set(“IAX2/IAX-Redcliffe-2314”, “ROUTE_CIDSAVE=”" <0732845463>") in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:3] Set(“IAX2/IAX-Redcliffe-2314”, “MOHCLASS=default”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:4] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Set(TRUNKCIDOVERRIDE=0732053477)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:5] Set(“IAX2/IAX-Redcliffe-2314”, “_NODEST=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:6] Gosub(“IAX2/IAX-Redcliffe-2314”, “sub-record-check,s,1(out,33333333,)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:1] Set(“IAX2/IAX-Redcliffe-2314”, “REC_POLICY_MODE_SAVE=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:2] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?check”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (sub-record-check,s,7)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:7] Set(“IAX2/IAX-Redcliffe-2314”, “__MON_FMT=wav”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:8] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?next”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (sub-record-check,s,11)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:11] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Return()”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:12] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(__REC_POLICY_MODE=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:13] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?out,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:14] Set(“IAX2/IAX-Redcliffe-2314”, “__REC_STATUS=INITIALIZED”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:15] Set(“IAX2/IAX-Redcliffe-2314”, “NOW=1379026429”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:16] Set(“IAX2/IAX-Redcliffe-2314”, “__DAY=13”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:17] Set(“IAX2/IAX-Redcliffe-2314”, “__MONTH=09”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:18] Set(“IAX2/IAX-Redcliffe-2314”, “__YEAR=2013”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:19] Set(“IAX2/IAX-Redcliffe-2314”, “__TIMESTR=20130913-085349”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:20] Set(“IAX2/IAX-Redcliffe-2314”, “__FROMEXTEN=0732845463”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:21] Set(“IAX2/IAX-Redcliffe-2314”, “__CALLFILENAME=out-33333333-0732845463-20130913-085349-1379026429.47”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-record-check:22] Goto(“IAX2/IAX-Redcliffe-2314”, “out,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (sub-record-check,out,1)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [out@sub-record-check:1] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Set(__REC_POLICY_MODE=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [out@sub-record-check:2] GosubIf(“IAX2/IAX-Redcliffe-2314”, “0?record,1(exten,33333333,0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [out@sub-record-check:3] Return(“IAX2/IAX-Redcliffe-2314”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:7] Macro(“IAX2/IAX-Redcliffe-2314”, “dialout-trunk,1,33333333,on”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:1] Set(“IAX2/IAX-Redcliffe-2314”, “DIAL_TRUNK=1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“IAX2/IAX-Redcliffe-2314”, “0?sub-pincheck,s,1()”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?disabletrunk,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:4] Set(“IAX2/IAX-Redcliffe-2314”, “DIAL_NUMBER=33333333”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:5] Set(“IAX2/IAX-Redcliffe-2314”, “DIAL_TRUNK_OPTIONS=Ttr”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:6] Set(“IAX2/IAX-Redcliffe-2314”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?nomax”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:8] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?chanfull”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?skipoutcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:10] Set(“IAX2/IAX-Redcliffe-2314”, “DIAL_TRUNK_OPTIONS=Tt”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:11] Macro(“IAX2/IAX-Redcliffe-2314”, “outbound-callerid,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(CALLERPRES()=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(REALCALLERIDNUM=0732845463)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?normcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (macro-outbound-callerid,s,6)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“IAX2/IAX-Redcliffe-2314”, “USEROUTCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“IAX2/IAX-Redcliffe-2314”, “EMERGENCYCID=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“IAX2/IAX-Redcliffe-2314”, “TRUNKOUTCID=0732053477”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?trunkcid”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (macro-outbound-callerid,s,14)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Set(CALLERID(all)=0732053477)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(CALLERID(all)=)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:16] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Set(CALLERID(all)=0732053477)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:17] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:18] Set(“IAX2/IAX-Redcliffe-2314”, “CDR(outbound_cnum)=0732053477”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-outbound-callerid:19] Set(“IAX2/IAX-Redcliffe-2314”, “CDR(outbound_cnam)=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:12] GosubIf(“IAX2/IAX-Redcliffe-2314”, “1?sub-flp-1,s,1()”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-flp-1:1] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Return()”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@sub-flp-1:2] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Return()”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:13] Set(“IAX2/IAX-Redcliffe-2314”, “OUTNUM=33333333”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:14] Set(“IAX2/IAX-Redcliffe-2314”, “custom=DAHDI/r1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:16] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:17] Macro(“IAX2/IAX-Redcliffe-2314”, “dialout-trunk-predial-hook,”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“IAX2/IAX-Redcliffe-2314”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?bypass,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:19] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(CONNECTEDLINE(num,i)=33333333)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:20] ExecIf(“IAX2/IAX-Redcliffe-2314”, “0?Set(CONNECTEDLINE(name,i)=CID:0732053477)”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?customtrunk”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“IAX2/IAX-Redcliffe-2314”, “DAHDI/r1/33333333,300,Tt”) in new stack
[2013-09-13 08:53:49] WARNING[22802][C-00000028] app_dial.c: Unable to create channel of type ‘DAHDI’ (cause 34 - Circuit/channel congestion)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] app_dial.c: == Everyone is busy/congested at this time (1:0/1/0)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:23] NoOp(“IAX2/IAX-Redcliffe-2314”, “Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 34”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@macro-dialout-trunk:24] GotoIf(“IAX2/IAX-Redcliffe-2314”, “1?continue,1:s-CONGESTION,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (macro-dialout-trunk,continue,1)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [continue@macro-dialout-trunk:1] NoOp(“IAX2/IAX-Redcliffe-2314”, “TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 34 - failing through to other trunks”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [continue@macro-dialout-trunk:2] Set(“IAX2/IAX-Redcliffe-2314”, “CALLERID(number)=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:8] Set(“IAX2/IAX-Redcliffe-2314”, “CALLERID(all)=”" <0732845463>") in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:9] Set(“IAX2/IAX-Redcliffe-2314”, “_KEEPCID=TRUE”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [33333333@from-internal:10] Goto(“IAX2/IAX-Redcliffe-2314”, “ivr-2,s,1”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Goto (ivr-2,s,1)
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:1] Set(“IAX2/IAX-Redcliffe-2314”, “_IVR_CONTEXT_ivr-2=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:2] Set(“IAX2/IAX-Redcliffe-2314”, “_IVR_CONTEXT=ivr-2”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:3] Set(“IAX2/IAX-Redcliffe-2314”, “__IVR_RETVM=”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:4] GotoIf(“IAX2/IAX-Redcliffe-2314”, “0?skip”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:5] Answer(“IAX2/IAX-Redcliffe-2314”, “”) in new stack
[2013-09-13 08:53:49] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:6] Wait(“IAX2/IAX-Redcliffe-2314”, “1”) in new stack
[2013-09-13 08:53:50] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:7] Set(“IAX2/IAX-Redcliffe-2314”, “IVR_MSG=custom/Closed”) in new stack
[2013-09-13 08:53:50] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:8] Set(“IAX2/IAX-Redcliffe-2314”, “TIMEOUT(digit)=3”) in new stack
[2013-09-13 08:53:50] VERBOSE[22802][C-00000028] func_timeout.c: – Digit timeout set to 3.000
[2013-09-13 08:53:50] VERBOSE[22802][C-00000028] pbx.c: – Executing [s@ivr-2:9] ExecIf(“IAX2/IAX-Redcliffe-2314”, “1?Background(custom/Closed)”) in new stack
[2013-09-13 08:53:50] VERBOSE[22802][C-00000028] file.c: – <IAX2/IAX-Redcliffe-2314> Playing ‘custom/Closed.slin’ (language ‘en’)
[2013-09-13 08:53:52] VERBOSE[22802][C-00000028] pbx.c: == Spawn extension (ivr-2, s, 9) exited non-zero on ‘IAX2/IAX-Redcliffe-2314’

Well I’d love to say it was something highly technical but it was a simple oversight. I had a congestion destination to ivr-2 in the outboud route on PBX-A for earlier testing. Set it to blank and the call terminated as expected.

Lost about 3 hours on that one. Sorry for wasting anyone else’s time.