Cant get followme to terminate a call if no answer ( Goto (app-blackhole,hangup,1))

bksales · January 18, 2018, 10:57pm

Follow Me is set for 0 initial ring time and then to follow for 20 seconds and then hangup. It is only following itself. I see it rings 20 seconds, the pbx claims its hanging up but then the ringing sound changes and it appears to start another call. I let this loop several times and it appears to never hangup.

I think its silly to want the phones to do this but thats what they want and I’m trying to make it work. Any ideas?

Here is what I see in putty:

-- SIP/253-00000516 is ringing
-- Nobody picked up in 20000 ms
-- SIP/253-00000516 Internal Gosub(crm-hangup,s,1) start

it goes through the motions of hanging up and then I see this but the caller hears ringing still

-- Goto (app-blackhole,hangup,1)

== Extension Changed 253[ext-local] new state Idle for Notify User 209
== Extension Changed 253[ext-local] new state Idle for Notify User 251
== Extension Changed 253[ext-local] new state Idle for Notify User 206
== Extension Changed 253[ext-local] new state Idle for Notify User 203

It rings for another 20 seconds and then checks time conditions and such again, changes the state back to ringing, rings for another 20 seconds, and then repeats the above message(s) and continues to ring. I didn’t go any further than this but i suspect it will ring forever.

dicko · January 18, 2018, 11:00pm

What about the ensuing log lines for the FollowMe extensions setup for 253?

bksales · January 18, 2018, 11:35pm

When I call from a cell phone (ATT) it works fine and terminates the call. My calls were originally all from another freepbx instance. I did a couple calls with the carrier watching and they could see that calls are failing on the primary inbound trunk and going through on the secondary.

What it appears is happening is every 20 seconds the PBX I’m calling from is trying again and during that 20 seconds its failing through all the outbound trunks. From the calling side I see this in the CDR

and from the receiving side i see this in the CDR

This number is on Level 3 so all calls regardless of origin should come from Level 3 to the Voip Innovations and then on to the PBX. Maybe it behaves different if the call is on net (never leaving the VI network)?

dicko · January 18, 2018, 11:36pm

Logs, logs, logs, no logs no clairyoyance

bksales · January 19, 2018, 1:17am

Here is everything. The VI-Outbound trunk is actually what is getting used as a failover inbound trunk, which may have something do with this.

-- Executing [XXXXXXX@from-pstn-e164-us:1] Goto("SIP/VI-Outbound_64.136.174.30-00000515", "from-pstn,XXXXXXX,1") in new stack
-- Goto (from-pstn,XXXXXXX,1)
-- Executing [XXXXXXX@from-pstn:1] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__DIRECTION=INBOUND") in new stack
-- Executing [XXXXXXX@from-pstn:2] Gosub("SIP/VI-Outbound_64.136.174.30-00000515", "app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:3] Return("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [XXXXXXX@from-pstn:3] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__FROM_DID=XXXXXXX") in new stack
-- Executing [XXXXXXX@from-pstn:4] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CDR(did)=XXXXXXX") in new stack
-- Executing [XXXXXXX@from-pstn:5] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0 ?Set(CALLERID(name)=YYYYYYYYYY)") in new stack
-- Executing [XXXXXXX@from-pstn:6] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__MOHCLASS=") in new stack
-- Executing [XXXXXXX@from-pstn:7] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__REVERSAL_REJECT=FALSE") in new stack
-- Executing [XXXXXXX@from-pstn:8] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?post-reverse-charge") in new stack
-- Goto (from-pstn,XXXXXXX,10)
-- Executing [XXXXXXX@from-pstn:10] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [XXXXXXX@from-pstn:11] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
-- Executing [XXXXXXX@from-pstn:12] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
-- Executing [XXXXXXX@from-pstn:13] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLERID(name-pres)=allowed_not_screened") in new stack
-- Executing [XXXXXXX@from-pstn:14] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLERID(num-pres)=allowed_not_screened") in new stack
-- Executing [XXXXXXX@from-pstn:15] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "CallerID Entry Point") in new stack
-- Executing [XXXXXXX@from-pstn:16] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__CRM_DIRECTION=INBOUND") in new stack
-- Executing [XXXXXXX@from-pstn:17] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__CRM_SOURCE=YYYYYYYYYY") in new stack
-- Executing [XXXXXXX@from-pstn:18] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__CRM_LINKEDID=1516315391.1456") in new stack
-- Executing [XXXXXXX@from-pstn:19] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
-- Executing [XXXXXXX@from-pstn:20] Goto("SIP/VI-Outbound_64.136.174.30-00000515", "from-did-direct,253,1") in new stack
-- Goto (from-did-direct,253,1)
-- Executing [253@from-did-direct:1] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?ext-local,253,1:followme-check,253,1") in new stack
-- Goto (followme-check,253,1)
-- Executing [253@followme-check:1] Gosub("SIP/VI-Outbound_64.136.174.30-00000515", "followme-sub,253,1()") in new stack
-- Executing [253@followme-sub:1] Macro("SIP/VI-Outbound_64.136.174.30-00000515", "user-callerid,") in new stack
-- Executing [s@macro-user-callerid:1] Set("SIP/VI-Outbound_64.136.174.30-00000515", "TOUCH_MONITOR=1516315391.1456") in new stack
-- Executing [s@macro-user-callerid:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "AMPUSER=YYYYYYYYYY") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?Set(REALCALLERIDNUM=YYYYYYYYYY)") in new stack
-- Executing [s@macro-user-callerid:5] Set("SIP/VI-Outbound_64.136.174.30-00000515", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:6] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?limit") in new stack
-- Executing [s@macro-user-callerid:7] Set("SIP/VI-Outbound_64.136.174.30-00000515", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:8] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?report") in new stack
-- Goto (macro-user-callerid,s,15)
-- Executing [s@macro-user-callerid:15] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Macro Depth is 1") in new stack
-- Executing [s@macro-user-callerid:16] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?report2:macroerror") in new stack
-- Goto (macro-user-callerid,s,18)
-- Executing [s@macro-user-callerid:18] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?continue") in new stack
-- Executing [s@macro-user-callerid:19] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:20] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?continue") in new stack
-- Goto (macro-user-callerid,s,36)
-- Executing [s@macro-user-callerid:36] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLERID(number)=YYYYYYYYYY") in new stack
-- Executing [s@macro-user-callerid:37] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLERID(name)=YYYYYYYYYY") in new stack
-- Executing [s@macro-user-callerid:38] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?cnum") in new stack
-- Executing [s@macro-user-callerid:39] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CDR(cnam)=YYYYYYYYYY") in new stack
-- Executing [s@macro-user-callerid:40] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CDR(cnum)=YYYYYYYYYY") in new stack
-- Executing [s@macro-user-callerid:41] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CHANNEL(language)=en") in new stack
-- Executing [253@followme-sub:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "DIAL_OPTIONS=TtrI") in new stack
-- Executing [253@followme-sub:3] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CONNECTEDLINE(num,i)=253") in new stack
-- Executing [253@followme-sub:4] Gosub("SIP/VI-Outbound_64.136.174.30-00000515", "sub-presencestate-display,s,1(253)") in new stack
-- Executing [s@sub-presencestate-display:1] Goto("SIP/VI-Outbound_64.136.174.30-00000515", "state-not_set,1") in new stack
-- Goto (sub-presencestate-display,state-not_set,1)
-- Executing [state-not_set@sub-presencestate-display:1] Set("SIP/VI-Outbound_64.136.174.30-00000515", "PRESENCESTATE_DISPLAY=") in new stack
-- Executing [state-not_set@sub-presencestate-display:2] Return("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [253@followme-sub:5] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CONNECTEDLINE(name)=Large Conf Room") in new stack
-- Executing [253@followme-sub:6] Set("SIP/VI-Outbound_64.136.174.30-00000515", "FM_DIALSTATUS=NOT_INUSE") in new stack
-- Executing [253@followme-sub:7] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__EXTTOCALL=253") in new stack
-- Executing [253@followme-sub:8] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__PICKUPMARK=253") in new stack
-- Executing [253@followme-sub:9] Macro("SIP/VI-Outbound_64.136.174.30-00000515", "blkvm-setifempty,") in new stack
-- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?init") in new stack
-- Goto (macro-blkvm-setifempty,s,4)
-- Executing [s@macro-blkvm-setifempty:4] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__BLKVM_CHANNEL=SIP/VI-Outbound_64.136.174.30-00000515") in new stack
-- Executing [s@macro-blkvm-setifempty:5] Set("SIP/VI-Outbound_64.136.174.30-00000515", "SHARED(BLKVM,SIP/VI-Outbound_64.136.174.30-00000515)=TRUE") in new stack
-- Executing [s@macro-blkvm-setifempty:6] Set("SIP/VI-Outbound_64.136.174.30-00000515", "GOSUB_RETVAL=TRUE") in new stack
-- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [253@followme-sub:10] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?skipov") in new stack
-- Goto (followme-sub,253,13)
-- Executing [253@followme-sub:13] Set("SIP/VI-Outbound_64.136.174.30-00000515", "RRNODEST=") in new stack
-- Executing [253@followme-sub:14] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__NODEST=253") in new stack
-- Executing [253@followme-sub:15] GosubIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?sub-fmsetcid,s,1()") in new stack
-- Executing [253@followme-sub:16] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?skipprepend") in new stack
-- Goto (followme-sub,253,18)
-- Executing [253@followme-sub:18] Set("SIP/VI-Outbound_64.136.174.30-00000515", "RecordMethod=Group") in new stack
-- Executing [253@followme-sub:19] Gosub("SIP/VI-Outbound_64.136.174.30-00000515", "sub-record-check,s,1(exten,253,)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?initialized") in new stack
-- Executing [s@sub-record-check:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:3] Set("SIP/VI-Outbound_64.136.174.30-00000515", "NOW=1516315391") in new stack
-- Executing [s@sub-record-check:4] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__DAY=18") in new stack
-- Executing [s@sub-record-check:5] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__MONTH=01") in new stack
-- Executing [s@sub-record-check:6] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__YEAR=2018") in new stack
-- Executing [s@sub-record-check:7] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__TIMESTR=20180118-144311") in new stack
-- Executing [s@sub-record-check:8] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__FROMEXTEN=YYYYYYYYYY") in new stack
-- Executing [s@sub-record-check:9] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:10] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/VI-Outbound_64.136.174.30-00000515", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "5?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?sub-record-check,exten,1") in new stack
-- Goto (sub-record-check,exten,1)
-- Executing [exten@sub-record-check:1] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Exten Recording Check between YYYYYYYYYY and 253") in new stack
-- Executing [exten@sub-record-check:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLTYPE=external") in new stack
-- Executing [exten@sub-record-check:3] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(CALLTYPE=)") in new stack
-- Executing [exten@sub-record-check:4] Set("SIP/VI-Outbound_64.136.174.30-00000515", "CALLEE=dontcare") in new stack
-- Executing [exten@sub-record-check:5] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(CALLEE=dontcare)") in new stack
-- Executing [exten@sub-record-check:6] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?callee") in new stack
-- Goto (sub-record-check,exten,11)
-- Executing [exten@sub-record-check:11] Gosub("SIP/VI-Outbound_64.136.174.30-00000515", "recordcheck,1(dontcare,external,253)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/VI-Outbound_64.136.174.30-00000515", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [exten@sub-record-check:12] Return("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [253@followme-sub:20] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?skipdring") in new stack
-- Goto (followme-sub,253,23)
-- Executing [253@followme-sub:23] Set("SIP/VI-Outbound_64.136.174.30-00000515", "STRATEGY=ringall") in new stack
-- Executing [253@followme-sub:24] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__RVOL=") in new stack
-- Executing [253@followme-sub:25] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?skipsimple") in new stack
-- Executing [253@followme-sub:26] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1 ?skipsimple") in new stack
-- Goto (followme-sub,253,28)
-- Executing [253@followme-sub:28] Set("SIP/VI-Outbound_64.136.174.30-00000515", "RingGroupMethod=ringall") in new stack
-- Executing [253@followme-sub:29] Set("SIP/VI-Outbound_64.136.174.30-00000515", "_FMGRP=253") in new stack
-- Executing [253@followme-sub:30] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?DIALGRP") in new stack
-- Goto (followme-sub,253,34)
-- Executing [253@followme-sub:34] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "1?Set(DOPTS=TtrI):Set(DOPTS=m(Ring)TtI)") in new stack
-- Executing [253@followme-sub:35] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?doconfirm") in new stack
-- Executing [253@followme-sub:36] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?ringallv21") in new stack
-- Executing [253@followme-sub:37] Macro("SIP/VI-Outbound_64.136.174.30-00000515", "dial,20,TtrI,253") in new stack
-- Executing [s@macro-dial:1] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
-- Executing [s@macro-dial:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__CRM_SOURCE=YYYYYYYYYY") in new stack
-- Executing [s@macro-dial:3] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(ALERT_INFO=)") in new stack
-- Executing [s@macro-dial:4] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(ALERT_INFO=)") in new stack
-- Executing [s@macro-dial:5] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(ALERT_INFO=)") in new stack
-- Executing [s@macro-dial:6] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(CHANNEL(musicclass)=)") in new stack
-- Executing [s@macro-dial:7] AGI("SIP/VI-Outbound_64.136.174.30-00000515", "dialparties.agi") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
-- dialparties.agi: Starting New Dialparties.agi
-- dialparties.agi: Caller ID name is 'YYYYYYYYYY' number is 'YYYYYYYYYY'
-- dialparties.agi: CW Ignore is:
-- dialparties.agi: CF Ignore is:
-- dialparties.agi: CW IN_USE/BUSY is: 1
-- dialparties.agi: USE_CONFIRMATION:  'FALSE'
-- dialparties.agi: RINGGROUP_INDEX:   ''
-- dialparties.agi: Methodology of ring is  'ringall'
-- dialparties.agi: Added extension 253 to extension map
-- dialparties.agi: Extension 253 has call screening off
-- dialparties.agi: Extension 253 cf is disabled
-- dialparties.agi: Extension 253 do not disturb is disabled
-- dialparties.agi: extnum 253 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
-- dialparties.agi: dbset CALLTRACE/253 to YYYYYYYYYY
-- dialparties.agi: Filtered ARG3: 253
-- dialparties.agi: NODEST: 253 adding M(auto-blkvm) to dialopts: TtrIM(auto-blkvm)
-- dialparties.agi: NODEST: 253 blkvm enabled macro already in dialopts: TtrIM(auto-blkvm)
-- <SIP/VI-Outbound_64.136.174.30-00000515>AGI Script dialparties.agi completed, returning 0
-- Executing [s@macro-dial:10] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Returned from dialparties with groups to dial") in new stack
-- Executing [s@macro-dial:11] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "ringall array  ") in new stack
-- Executing [s@macro-dial:12] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__FMGL_DIAL=") in new stack
-- Executing [s@macro-dial:13] Set("SIP/VI-Outbound_64.136.174.30-00000515", "LOOPCNT=1") in new stack
-- Executing [s@macro-dial:14] Set("SIP/VI-Outbound_64.136.174.30-00000515", "ITER=1") in new stack
-- Executing [s@macro-dial:15] Set("SIP/VI-Outbound_64.136.174.30-00000515", "EXTTOCALL=253") in new stack
-- Executing [s@macro-dial:16] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Working with 253") in new stack
-- Executing [s@macro-dial:17] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
-- Executing [s@macro-dial:18] ExecIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
-- Executing [s@macro-dial:19] Set("SIP/VI-Outbound_64.136.174.30-00000515", "ITER=2") in new stack
-- Executing [s@macro-dial:20] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?ndloopbegin") in new stack
-- Executing [s@macro-dial:21] Macro("SIP/VI-Outbound_64.136.174.30-00000515", "dial-ringall-predial-hook,") in new stack
-- Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [s@macro-dial:22] Dial("SIP/VI-Outbound_64.136.174.30-00000515", "SIP/253,20,trIM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
-- Using SIP RTP TOS bits 184
-- Using SIP RTP CoS mark 5
-- SIP/253-00000516 Internal Gosub(func-apply-sipheaders,s,1) start
-- Executing [s@func-apply-sipheaders:1] ExecIf("SIP/253-00000516", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
-- Executing [s@func-apply-sipheaders:2] NoOp("SIP/253-00000516", "Applying SIP Headers to channel") in new stack
-- Executing [s@func-apply-sipheaders:3] Set("SIP/253-00000516", "SIPHEADERKEYS=") in new stack
-- Executing [s@func-apply-sipheaders:4] While("SIP/253-00000516", "0") in new stack
-- Jumping to priority 7
-- Executing [s@func-apply-sipheaders:8] Return("SIP/253-00000516", "") in new stack
-- Spawn extension (from-internal, 253, 1) exited non-zero on 'SIP/253-00000516'
-- SIP/253-00000516 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
-- Extension Changed 253[ext-local] new state Ringing for Notify User 209
-- Extension Changed 253[ext-local] new state Ringing for Notify User 251
-- Extension Changed 253[ext-local] new state Ringing for Notify User 206
-- Extension Changed 253[ext-local] new state Ringing for Notify User 203
-- Called SIP/253
-- Connected line update to SIP/VI-Outbound_64.136.174.30-00000515 prevented.
-- SIP/253-00000516 is ringing
-- Nobody picked up in 20000 ms
-- SIP/253-00000516 Internal Gosub(crm-hangup,s,1) start
-- Executing [s@crm-hangup:1] NoOp("SIP/253-00000516", "Sending Hangup to CRM") in new stack
-- Executing [s@crm-hangup:2] NoOp("SIP/253-00000516", "HANGUP CAUSE: 16") in new stack
-- Executing [s@crm-hangup:3] ExecIf("SIP/253-00000516", "0?Set(__CRM_VOICEMAIL=)") in new stack
-- Executing [s@crm-hangup:4] NoOp("SIP/253-00000516", "MASTER CHANNEL: 1516315391.1457 = 1516315391.1456") in new stack
-- Executing [s@crm-hangup:5] GotoIf("SIP/253-00000516", "1?return") in new stack
-- Goto (crm-hangup,s,8)
-- Executing [s@crm-hangup:8] Return("SIP/253-00000516", "") in new stack
-- Spawn extension (from-internal, 253, 1) exited non-zero on 'SIP/253-00000516'
-- SIP/253-00000516 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
-- Executing [s@macro-dial:23] Set("SIP/VI-Outbound_64.136.174.30-00000515", "DIALSTATUS=NOANSWER") in new stack
-- Executing [s@macro-dial:24] GosubIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?NOANSWER,1()") in new stack
-- Executing [s@macro-dial:25] NoOp("SIP/VI-Outbound_64.136.174.30-00000515", "Returning since nobody answered") in new stack
-- Executing [s@macro-dial:26] MacroExit("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [253@followme-sub:38] Goto("SIP/VI-Outbound_64.136.174.30-00000515", "nextstep") in new stack
-- Goto (followme-sub,253,45)
-- Executing [253@followme-sub:45] Set("SIP/VI-Outbound_64.136.174.30-00000515", "RingGroupMethod=") in new stack
-- Executing [253@followme-sub:46] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?nodest") in new stack
-- Executing [253@followme-sub:47] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__NODEST=") in new stack
-- Executing [253@followme-sub:48] Set("SIP/VI-Outbound_64.136.174.30-00000515", "__PICKUPMARK=") in new stack
-- Executing [253@followme-sub:49] Macro("SIP/VI-Outbound_64.136.174.30-00000515", "blkvm-clr,") in new stack
-- Executing [s@macro-blkvm-clr:1] Set("SIP/VI-Outbound_64.136.174.30-00000515", "SHARED(BLKVM,SIP/VI-Outbound_64.136.174.30-00000515)=") in new stack
-- Executing [s@macro-blkvm-clr:2] Set("SIP/VI-Outbound_64.136.174.30-00000515", "GOSUB_RETVAL=") in new stack
-- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/VI-Outbound_64.136.174.30-00000515", "") in new stack
-- Executing [253@followme-sub:50] Set("SIP/VI-Outbound_64.136.174.30-00000515", "DIALSTATUS=NOANSWER") in new stack
-- Executing [253@followme-sub:51] GotoIf("SIP/VI-Outbound_64.136.174.30-00000515", "0?dohangup") in new stack
-- Executing [253@followme-sub:52] Goto("SIP/VI-Outbound_64.136.174.30-00000515", "app-blackhole,hangup,1") in new stack
-- Goto (app-blackhole,hangup,1)

bksales · January 19, 2018, 1:29am

I think I have an outbound trunk definition problem. I just tried this on a different PBX and when i call from a cell phone it works fine and comes in on the correct trunk but when i call out from a soft phone connected to another freepbx system it fails on the primary inbound trunk and fails to the secondary trunk. At least I have somewhere to look.

dicko · January 19, 2018, 1:51am

Gotta love reading the logs

bksales · January 19, 2018, 3:19am

After dragging VI into this I think we got this going. The issue may not be unique to VI but we’ve learned the following:

VI to VI calls intentionally use that secondary inbound trunk, so thats not a concern.
Calls that originate using that secondary trunk will retry if they dont connect. For that reason the originating PBX will not stop trying the call and you end up with some endless loop if the other PBX never answers, even if it shows (on both PBXs) as a bunch of unique calls.
If the PBX answers the call in any way before hanging up this all goes away. So I made an announcement with no greeting and had the announcement terminate the call.

I still dont know what this app-blackhole is though, other than it really is a black hole of sorts where the call never gets answered or terminated.

dicko · January 19, 2018, 3:31am

your VI endpoint management should have a “pop up” list of primary through quaternary servers to expect traffic from, you should have an inbound trunk for each, But if you didn’t screw up your trunks, the primary should work. 99.999%

bksales · January 19, 2018, 6:17pm

Thats the first thing I checked, and the VI trunks are all there and configured correctly. The issue is with the behavior of on net vs off net calls. According to the guy I talked to at tech support at least all on net (VI to VI) calls will come in on that secondary inbound trunk, and what we eventually figured out is that that trunk behaves differently than the primary trunk despite them being configured exactly the same on the pbx.

system · January 19, 2019, 6:17pm

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