Ring groups no longer works after latest module updates [Resolved]

necits2015 · April 8, 2016, 9:49pm

After the latest round of module updates the ring group no longer works when set as in inbound route destination. The extension will ring but as soon as the call is picked up the call ends. Setting the extension (101) as the destination works normally.

necits2015 · April 8, 2016, 10:41pm

Thought it may have something to do with the alert-info so i removed it but still no luck. I believe this is the culprit… WARNING[30156][C-00000003] app_dial.c: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)

jfinstrom · April 8, 2016, 11:05pm

can you supply a full (text) call trace start to finish

Also I added a sip and PJSIP extension to a ring group and all worked fine.

necits2015 · April 8, 2016, 11:25pm

Sure thing!

[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk-sip-GV1860xxxxxxx:1] Set("SIP/GV1860xxxxxxx-00000006", "GROUP()=OUT_3") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk-sip-GV1860xxxxxxx:2] Goto("SIP/GV1860xxxxxxx-00000006", "from-trunk,1860xxxxxxx,1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (from-trunk,1860xxxxxxx,1)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:1] Set("SIP/GV1860xxxxxxx-00000006", "__FROM_DID=1860xxxxxxx") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:2] Gosub("SIP/GV1860xxxxxxx-00000006", "sub-record-check,s,1(in,1860xxxxxxx,dontcare)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?initialized") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:2] Set("SIP/GV1860xxxxxxx-00000006", "__REC_STATUS=INITIALIZED") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:3] Set("SIP/GV1860xxxxxxx-00000006", "NOW=1460152572") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:4] Set("SIP/GV1860xxxxxxx-00000006", "__DAY=08") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:5] Set("SIP/GV1860xxxxxxx-00000006", "__MONTH=04") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/GV1860xxxxxxx-00000006", "__YEAR=2016") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/GV1860xxxxxxx-00000006", "__TIMESTR=20160408-175612") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:8] Set("SIP/GV1860xxxxxxx-00000006", "__FROMEXTEN=unknown") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:9] Set("SIP/GV1860xxxxxxx-00000006", "__MON_FMT=wav") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/GV1860xxxxxxx-00000006", "Recordings initialized") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(ARG3=dontcare)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/GV1860xxxxxxx-00000006", "REC_POLICY_MODE_SAVE=") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(REC_STATUS=NO)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/GV1860xxxxxxx-00000006", "2?checkaction") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (sub-record-check,s,17)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/GV1860xxxxxxx-00000006", "1?sub-record-check,in,1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (sub-record-check,in,1)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [in@sub-record-check:1] NoOp("SIP/GV1860xxxxxxx-00000006", "Inbound Recording Check to 1860xxxxxxx") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [in@sub-record-check:2] Set("SIP/GV1860xxxxxxx-00000006", "FROMEXTEN=unknown") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [in@sub-record-check:3] ExecIf("SIP/GV1860xxxxxxx-00000006", "10?Set(FROMEXTEN=860xxxxxxx)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [in@sub-record-check:4] Gosub("SIP/GV1860xxxxxxx-00000006", "recordcheck,1(dontcare,in,1860xxxxxxx)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/GV1860xxxxxxx-00000006", "Starting recording check against dontcare") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/GV1860xxxxxxx-00000006", "dontcare") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (sub-record-check,recordcheck,3)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [recordcheck@sub-record-check:3] Return("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [in@sub-record-check:5] Return("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:3] Gosub("SIP/GV1860xxxxxxx-00000006", "app-blacklist-check,s,1()") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?blacklisted") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/GV1860xxxxxxx-00000006", "CALLED_BLACKLIST=1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:4] Set("SIP/GV1860xxxxxxx-00000006", "CDR(did)=1860xxxxxxx") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:5] ExecIf("SIP/GV1860xxxxxxx-00000006", "0 ?Set(CALLERID(name)=860xxxxxxx)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:6] Set("SIP/GV1860xxxxxxx-00000006", "__MOHCLASS=") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:7] Set("SIP/GV1860xxxxxxx-00000006", "__REVERSAL_REJECT=FALSE") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:8] GotoIf("SIP/GV1860xxxxxxx-00000006", "1?post-reverse-charge") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (from-trunk,1860xxxxxxx,10)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:10] NoOp("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:11] Set("SIP/GV1860xxxxxxx-00000006", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:12] Set("SIP/GV1860xxxxxxx-00000006", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:13] Set("SIP/GV1860xxxxxxx-00000006", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:14] Set("SIP/GV1860xxxxxxx-00000006", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:15] NoOp("SIP/GV1860xxxxxxx-00000006", "CallerID Entry Point") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [1860xxxxxxx@from-trunk:16] Goto("SIP/GV1860xxxxxxx-00000006", "ext-group,600,1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (ext-group,600,1)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:1] Progress("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:2] Macro("SIP/GV1860xxxxxxx-00000006", "user-callerid,") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/GV1860xxxxxxx-00000006", "TOUCH_MONITOR=1460152572.6") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/GV1860xxxxxxx-00000006", "AMPUSER=860xxxxxxx") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?report") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/GV1860xxxxxxx-00000006", "1?Set(REALCALLERIDNUM=860xxxxxxx)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/GV1860xxxxxxx-00000006", "AMPUSER=") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?limit") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/GV1860xxxxxxx-00000006", "AMPUSERCIDNAME=") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/GV1860xxxxxxx-00000006", "1?report") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,15)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?continue") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:16] ExecIf("SIP/GV1860xxxxxxx-00000006", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:17] Set("SIP/GV1860xxxxxxx-00000006", "__TTL=64") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:18] GotoIf("SIP/GV1860xxxxxxx-00000006", "1?continue") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,29)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/GV1860xxxxxxx-00000006", "CALLERID(number)=860xxxxxxx") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/GV1860xxxxxxx-00000006", "CALLERID(name)=M MATHEWSON") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/GV1860xxxxxxx-00000006", "CDR(cnum)=860xxxxxxx") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/GV1860xxxxxxx-00000006", "CDR(cnam)=M MATHEWSON") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/GV1860xxxxxxx-00000006", "CHANNEL(language)=en") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:3] Macro("SIP/GV1860xxxxxxx-00000006", "blkvm-setifempty,") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/GV1860xxxxxxx-00000006", "1?init") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (macro-blkvm-setifempty,s,4)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/GV1860xxxxxxx-00000006", "__BLKVM_CHANNEL=SIP/GV1860xxxxxxx-00000006") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/GV1860xxxxxxx-00000006", "SHARED(BLKVM,SIP/GV1860xxxxxxx-00000006)=TRUE") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/GV1860xxxxxxx-00000006", "GOSUB_RETVAL=TRUE") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:4] GotoIf("SIP/GV1860xxxxxxx-00000006", "1?skipov") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (ext-group,600,7)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:7] Set("SIP/GV1860xxxxxxx-00000006", "RRNODEST=") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:8] Set("SIP/GV1860xxxxxxx-00000006", "__NODEST=600") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:9] GosubIf("SIP/GV1860xxxxxxx-00000006", "0?sub-rgsetcid,s,1()") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:10] Gosub("SIP/GV1860xxxxxxx-00000006", "sub-record-check,s,1(rg,600,dontcare)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/GV1860xxxxxxx-00000006", "10?initialized") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (sub-record-check,s,10)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/GV1860xxxxxxx-00000006", "Recordings initialized") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(ARG3=dontcare)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/GV1860xxxxxxx-00000006", "REC_POLICY_MODE_SAVE=") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(REC_STATUS=NO)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/GV1860xxxxxxx-00000006", "2?checkaction") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (sub-record-check,s,17)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?sub-record-check,rg,1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:18] NoOp("SIP/GV1860xxxxxxx-00000006", "Generic rg Recording Check - 860xxxxxxx 600") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:19] Gosub("SIP/GV1860xxxxxxx-00000006", "recordcheck,1(dontcare,rg,600)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/GV1860xxxxxxx-00000006", "Starting recording check against dontcare") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/GV1860xxxxxxx-00000006", "dontcare") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Goto (sub-record-check,recordcheck,3)
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [recordcheck@sub-record-check:3] Return("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@sub-record-check:20] Return("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:11] Set("SIP/GV1860xxxxxxx-00000006", "RingGroupMethod=ringall") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [600@ext-group:12] Macro("SIP/GV1860xxxxxxx-00000006", "dial,20,Ttr,101") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:1] NoOp("SIP/GV1860xxxxxxx-00000006", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:2] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(ALERT_INFO=)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:3] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(ALERT_INFO=)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:4] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(ALERT_INFO=)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:5] ExecIf("SIP/GV1860xxxxxxx-00000006", "0?Set(CHANNEL(musicclass)=)") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:6] AGI("SIP/GV1860xxxxxxx-00000006", "dialparties.agi") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: dialparties.agi: Caller ID name is 'M MATHEWSON' number is '860xxxxxxx'
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- dialparties.agi: Added extension 101 to extension map
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- dialparties.agi: Extension 101 cf is disabled
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- dialparties.agi: Extension 101 do not disturb is disabled
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- dialparties.agi: dbset CALLTRACE/101 to 860xxxxxxx
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- dialparties.agi: Filtered ARG3: 101
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] res_agi.c: -- <SIP/GV1860xxxxxxx-00000006>AGI Script dialparties.agi completed, returning 0
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:9] NoOp("SIP/GV1860xxxxxxx-00000006", "Returned from dialparties with groups to dial") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:10] Set("SIP/GV1860xxxxxxx-00000006", "LOOPCNT=1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:11] Set("SIP/GV1860xxxxxxx-00000006", "ITER=1") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:12] Set("SIP/GV1860xxxxxxx-00000006", "EXTTOCALL=101") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:13] NoOp("SIP/GV1860xxxxxxx-00000006", "Working with 101") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:14] Set("SIP/GV1860xxxxxxx-00000006", "ITER=2") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:15] GotoIf("SIP/GV1860xxxxxxx-00000006", "0?ndloopbegin") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:16] Macro("SIP/GV1860xxxxxxx-00000006", "dial-ringall-predial-hook,") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/GV1860xxxxxxx-00000006", "") in new stack
[2016-04-08 17:56:12] VERBOSE[30156][C-00000003] pbx.c: -- Executing [s@macro-dial:17] Dial("SIP/GV1860xxxxxxx-00000006", "SIP/99101&SIP/101,20,TtrM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2016-04-08 17:56:12] WARNING[30156][C-00000003] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)

necits2015 · April 8, 2016, 11:29pm

This actually started on the “edge” track for me. I disabled edge and reverted back and everything worked fine however after the latest “normal” module updates I am experiencing the issues once again.

jfinstrom · April 8, 2016, 11:34pm

asterisk -rx 'core show channeltype SIP'
fwconsole ma list
fwconsole setting -d | grep ASTSIPDRIVER

necits2015 · April 8, 2016, 11:48pm

[root@necits ~]# asterisk -rx 'core show channeltype SIP'
-- Info about channel driver: SIP --
  Device State: yes
    Indication: yes
     Transfer : yes
  Capabilities: (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|speex16|ilb                                                                             c|g726aal2|g722|slin16|siren7|siren14|testlaw|g719|speex32|slin12|slin24|slin32|                                                                             slin44|slin48|slin96|slin192)
   Digit Begin: yes
     Digit End: yes
    Send HTML : yes
 Image Support: no
  Text Support: yes

[root@necits ~]# fwconsole ma list
No repos specified, using: [standard,extended,commercial] from last GUI settings

+----------------------+--------------+-----------------------------------+
| Module               | Version      | Status                            |
+----------------------+--------------+-----------------------------------+
| accountcodepreserve  | 13.0.2       | Enabled                           |
| announcement         | 13.0.5       | Enabled                           |
| areminder            | 13.0.4.2     | Disabled                          |
| arimanager           | 13.0.3       | Enabled                           |
| asterisk-cli         | 13.0.3       | Enabled                           |
| asteriskinfo         | 13.0.6       | Enabled                           |
| asternic_cdr         | 1.6.3        | Enabled                           |
| backup               | 13.0.21.8    | Enabled                           |
| blacklist            | 13.0.9       | Enabled                           |
| bria                 | 13.0.12      | Enabled                           |
| broadcast            | 13.0.10      | Enabled                           |
| builtin              |              | Enabled                           |
| bulkdids             | 13.0.2       | Enabled                           |
| bulkextensions       | 13.0.3       | Enabled                           |
| bulkhandler          | 13.0.13      | Enabled                           |
| callback             | 13.0.5       | Enabled                           |
| callerid             | 13.0.5       | Enabled                           |
| callforward          | 13.0.4       | Enabled                           |
| calllimit            | 13.0.2       | Disabled                          |
| callrecording        | 13.0.9       | Enabled                           |
| callwaiting          | 13.0.4       | Enabled                           |
| campon               | 13.0.3       | Disabled                          |
| cdr                  | 13.0.28      | Enabled                           |
| cel                  | 13.0.22      | Enabled                           |
| certman              | 13.0.12      | Enabled                           |
| cidlookup            | 13.0.10      | Enabled                           |
| conferences          | 13.0.18      | Enabled                           |
| conferencespro       | 13.0.20      | Enabled                           |
| configedit           | 13.0.7       | Enabled                           |
| contactmanager       | 13.0.23      | Enabled                           |
| core                 | 13.0.69      | Enabled                           |
| customappsreg        | 13.0.5       | Enabled                           |
| cxpanel              | 4.1.12       | Enabled                           |
| dahdiconfig          | 13.0.13      | Enabled                           |
| dashboard            | 13.0.21      | Enabled                           |
| daynight             | 13.0.9       | Enabled                           |
| dictate              | 13.0.4       | Enabled                           |
| digium_phones        | 2.11.3.0     | Disabled                          |
| digiumaddoninstaller | 2.11.0.12    | Disabled                          |
| directory            | 13.0.12      | Enabled                           |
| disa                 | 13.0.6       | Enabled                           |
| donotdisturb         | 13.0.3       | Enabled                           |
| endpoint             | 13.0.39      | Enabled                           |
| extensionroutes      | 13.0.8       | Enabled                           |
| extensionsettings    | 13.0.4       | Enabled                           |
| fax                  | 13.0.28      | Enabled                           |
| faxpro               | 13.0.25      | Disabled                          |
| featurecodeadmin     | 13.0.5       | Enabled                           |
| findmefollow         | 13.0.28      | Enabled                           |
| firewall             | 13.0.21.1    | Enabled                           |
| framework            | 13.0.102     | Enabled                           |
| freepbx_ha           | 13.0.3       | Disabled                          |
| fw_ari               |              | Not Installed (Locally available) |
| fw_langpacks         | 12.0.7       | Enabled                           |
| hotelwakeup          | 13.0.7       | Disabled                          |
| iaxsettings          | 13.0.4       | Enabled                           |
| infoservices         | 13.0.1       | Enabled                           |
| irc                  | 2.11.0.6     | Enabled                           |
| ivr                  | 13.0.23      | Enabled                           |
| languages            | 13.0.6       | Enabled                           |
| logfiles             | 13.0.9       | Enabled                           |
| manager              | 13.0.2.5     | Enabled                           |
| miscapps             | 13.0.2.2     | Enabled                           |
| miscdests            | 13.0.2       | Enabled                           |
| music                | 13.0.18      | Enabled                           |
| outroutemsg          | 13.0.2       | Enabled                           |
| paging               | 13.0.14      | Enabled                           |
| pagingpro            | 13.0.8       | Disabled                          |
| parking              | 13.0.14      | Enabled                           |
| parkpro              | 13.0.17      | Enabled                           |
| pbdirectory          | 2.11.0.4     | Enabled                           |
| phonebook            | 13.0.5.2     | Enabled                           |
| phpinfo              | 13.0.2       | Enabled                           |
| pinsets              | 13.0.7       | Enabled                           |
| pinsetspro           | 13.0.3       | Disabled                          |
| presencestate        | 13.0.4       | Enabled                           |
| printextensions      | 13.0.3       | Enabled                           |
| queueprio            | 13.0.2       | Enabled                           |
| queues               | 13.0.21      | Enabled                           |
| qxact_reports        | 13.0.8       | Disabled                          |
| recording_report     | 13.0.20      | Enabled                           |
| recordings           | 13.0.23      | Enabled                           |
| restapi              | 13.0.18.3    | Enabled                           |
| restapps             | 13.0.13      | Enabled                           |
| ringgroups           | 13.0.17      | Enabled                           |
| setcid               | 13.0.4       | Enabled                           |
| sipsettings          | 13.0.18      | Enabled                           |
| sipstation           | 13.0.13.9    | Enabled                           |
| sms                  | 13.0.6       | Enabled                           |
| sng_mcu              | 13.0.3       | Enabled                           |
| soundlang            | 13.0.10      | Enabled                           |
| speeddial            | 2.11.0.3     | Enabled                           |
| superfecta           | 13.0.3.10    | Enabled                           |
| sysadmin             | 13.0.50      | Enabled                           |
| timeconditions       | 13.0.26      | Enabled                           |
| tts                  | 13.0.7       | Enabled                           |
| ttsengines           | 13.0.4.1     | Enabled                           |
| ucp                  | 13.0.27      | Enabled                           |
| ucpnode              | 13.0.22      | Enabled                           |
| userman              | 13.0.55      | Enabled                           |
| vmblast              | 13.0.8       | Enabled                           |
| vmnotify             | 13.0.8       | Disabled                          |
| voicemail            | 13.0.39      | Enabled                           |
| voicemail_report     | 13.0.10      | Enabled                           |
| vqplus               | 13.0.16      | Disabled                          |
| weakpasswords        | 13.0.1alpha1 | Enabled                           |
| webcallback          | 13.0.10      | Enabled                           |
| webrtc               | 13.0.16      | Enabled                           |
| xmpp                 | 13.0.6       | Enabled                           |
+----------------------+--------------+-----------------------------------+

[root@necits ~]# fwconsole setting -d | grep ASTSIPDRIVER
ASTSIPDRIVER=chan_sip
[root@necits ~]#

necits2015 · April 9, 2016, 5:47pm

This only seems to happen when dialing in through the trunk. The ring group works correctly when dialed internally. Should I file a bug report?

tm1000 · April 10, 2016, 7:03am

At this point in time it does not appear to be a bug. Why? Because you went to edge. Had the issue. Went backwards and still have the issue. If you have the issue on both that doesn’t point to a bug

Also you’re getting subscriber absent because it’s dialing the webrtc client which is disconnected so that is very normal

Unfortunately you truncated your log right after it tried to dial Ext 101 so we can’t troubleshoot with what you’ve given. Please post the whole log.

necits2015 · April 10, 2016, 1:53pm

Thanks for the reply. So just to clarify. Things were working fine on normal track. I switched to edge track, updated modules and ring groups didn’t work. I reverted back to the normal track and everything worked correctly again. It wasn’t until after the latest round of updates on the normal track that I started having issues again. I will post the full log shortly.

necits2015 · April 10, 2016, 3:10pm

[2016-04-10 10:59:31] VERBOSE[3111][C-00000001] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk-sip-GV1860821xxxx:1] Set("SIP/GV1860821xxxx-00000001", "GROUP()=OUT_3") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk-sip-GV1860821xxxx:2] Goto("SIP/GV1860821xxxx-00000001", "from-trunk,1860821xxxx,1") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (from-trunk,1860821xxxx,1)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:1] Set("SIP/GV1860821xxxx-00000001", "__FROM_DID=1860821xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:2] Gosub("SIP/GV1860821xxxx-00000001", "sub-record-check,s,1(in,1860821xxxx,never)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/GV1860821xxxx-00000001", "0?initialized") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:2] Set("SIP/GV1860821xxxx-00000001", "__REC_STATUS=INITIALIZED") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:3] Set("SIP/GV1860821xxxx-00000001", "NOW=1460300371") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:4] Set("SIP/GV1860821xxxx-00000001", "__DAY=10") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:5] Set("SIP/GV1860821xxxx-00000001", "__MONTH=04") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:6] Set("SIP/GV1860821xxxx-00000001", "__YEAR=2016") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:7] Set("SIP/GV1860821xxxx-00000001", "__TIMESTR=20160410-105931") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:8] Set("SIP/GV1860821xxxx-00000001", "__FROMEXTEN=unknown") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:9] Set("SIP/GV1860821xxxx-00000001", "__MON_FMT=wav") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/GV1860821xxxx-00000001", "Recordings initialized") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(ARG3=dontcare)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:12] Set("SIP/GV1860821xxxx-00000001", "REC_POLICY_MODE_SAVE=") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(REC_STATUS=NO)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/GV1860821xxxx-00000001", "2?checkaction") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,s,17)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/GV1860821xxxx-00000001", "1?sub-record-check,in,1") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,in,1)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/GV1860821xxxx-00000001", "Inbound Recording Check to 1860821xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [in@sub-record-check:2] Set("SIP/GV1860821xxxx-00000001", "FROMEXTEN=unknown") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/GV1860821xxxx-00000001", "10?Set(FROMEXTEN=860324xxxx)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/GV1860821xxxx-00000001", "recordcheck,1(never,in,1860821xxxx)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/GV1860821xxxx-00000001", "Starting recording check against never") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/GV1860821xxxx-00000001", "never") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,recordcheck,14)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:14] Set("SIP/GV1860821xxxx-00000001", "__REC_POLICY_MODE=NEVER") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:15] Goto("SIP/GV1860821xxxx-00000001", "stoprec") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,recordcheck,25)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:25] NoOp("SIP/GV1860821xxxx-00000001", "Stopping recording: in, 1860821xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:26] Set("SIP/GV1860821xxxx-00000001", "__REC_STATUS=STOPPED") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:27] System("SIP/GV1860821xxxx-00000001", "/var/lib/asterisk/bin/stoprecording.php "SIP/GV1860821xxxx-00000001"") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:28] Return("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [in@sub-record-check:5] Return("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:3] Gosub("SIP/GV1860821xxxx-00000001", "app-blacklist-check,s,1()") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/GV1860821xxxx-00000001", "0?blacklisted") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/GV1860821xxxx-00000001", "CALLED_BLACKLIST=1") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:4] Set("SIP/GV1860821xxxx-00000001", "CDR(did)=1860821xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:5] ExecIf("SIP/GV1860821xxxx-00000001", "0 ?Set(CALLERID(name)=860324xxxx)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:6] Set("SIP/GV1860821xxxx-00000001", "__MOHCLASS=") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:7] Set("SIP/GV1860821xxxx-00000001", "__REVERSAL_REJECT=FALSE") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:8] GotoIf("SIP/GV1860821xxxx-00000001", "1?post-reverse-charge") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (from-trunk,1860821xxxx,10)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:10] NoOp("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:11] Set("SIP/GV1860821xxxx-00000001", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:12] Set("SIP/GV1860821xxxx-00000001", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:13] Set("SIP/GV1860821xxxx-00000001", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:14] Set("SIP/GV1860821xxxx-00000001", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:15] NoOp("SIP/GV1860821xxxx-00000001", "CallerID Entry Point") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [1860821xxxx@from-trunk:16] Goto("SIP/GV1860821xxxx-00000001", "ext-group,600,1") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (ext-group,600,1)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:1] Progress("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:2] Macro("SIP/GV1860821xxxx-00000001", "user-callerid,") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/GV1860821xxxx-00000001", "TOUCH_MONITOR=1460300371.13") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/GV1860821xxxx-00000001", "AMPUSER=860324xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/GV1860821xxxx-00000001", "0?report") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/GV1860821xxxx-00000001", "1?Set(REALCALLERIDNUM=860324xxxx)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/GV1860821xxxx-00000001", "AMPUSER=") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/GV1860821xxxx-00000001", "0?limit") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/GV1860821xxxx-00000001", "AMPUSERCIDNAME=") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/GV1860821xxxx-00000001", "1?report") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (macro-user-callerid,s,15)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/GV1860821xxxx-00000001", "0?continue") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:16] ExecIf("SIP/GV1860821xxxx-00000001", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/GV1860821xxxx-00000001", "__TTL=64") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/GV1860821xxxx-00000001", "1?continue") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (macro-user-callerid,s,29)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/GV1860821xxxx-00000001", "CALLERID(number)=860324xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/GV1860821xxxx-00000001", "CALLERID(name)=M MATHEWSON") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:31] Set("SIP/GV1860821xxxx-00000001", "CDR(cnum)=860324xxxx") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/GV1860821xxxx-00000001", "CDR(cnam)=M MATHEWSON") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-user-callerid:33] Set("SIP/GV1860821xxxx-00000001", "CHANNEL(language)=en") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:3] Macro("SIP/GV1860821xxxx-00000001", "blkvm-setifempty,") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/GV1860821xxxx-00000001", "1?init") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (macro-blkvm-setifempty,s,4)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/GV1860821xxxx-00000001", "__BLKVM_CHANNEL=SIP/GV1860821xxxx-00000001") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/GV1860821xxxx-00000001", "SHARED(BLKVM,SIP/GV1860821xxxx-00000001)=TRUE") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/GV1860821xxxx-00000001", "GOSUB_RETVAL=TRUE") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:4] GotoIf("SIP/GV1860821xxxx-00000001", "1?skipov") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (ext-group,600,7)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:7] Set("SIP/GV1860821xxxx-00000001", "RRNODEST=") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:8] Set("SIP/GV1860821xxxx-00000001", "__NODEST=600") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:9] GosubIf("SIP/GV1860821xxxx-00000001", "0?sub-rgsetcid,s,1()") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:10] Gosub("SIP/GV1860821xxxx-00000001", "sub-record-check,s,1(rg,600,never)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/GV1860821xxxx-00000001", "10?initialized") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,s,10)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/GV1860821xxxx-00000001", "Recordings initialized") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(ARG3=dontcare)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:12] Set("SIP/GV1860821xxxx-00000001", "REC_POLICY_MODE_SAVE=NEVER") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(REC_STATUS=NO)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/GV1860821xxxx-00000001", "2?checkaction") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,s,17)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/GV1860821xxxx-00000001", "0?sub-record-check,rg,1") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/GV1860821xxxx-00000001", "Generic rg Recording Check - 860324xxxx 600") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/GV1860821xxxx-00000001", "recordcheck,1(never,rg,600)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/GV1860821xxxx-00000001", "Starting recording check against never") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/GV1860821xxxx-00000001", "never") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,recordcheck,14)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:14] Set("SIP/GV1860821xxxx-00000001", "__REC_POLICY_MODE=NEVER") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:15] Goto("SIP/GV1860821xxxx-00000001", "stoprec") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Goto (sub-record-check,recordcheck,25)
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:25] NoOp("SIP/GV1860821xxxx-00000001", "Stopping recording: rg, 600") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:26] Set("SIP/GV1860821xxxx-00000001", "__REC_STATUS=STOPPED") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:27] System("SIP/GV1860821xxxx-00000001", "/var/lib/asterisk/bin/stoprecording.php "SIP/GV1860821xxxx-00000001"") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [recordcheck@sub-record-check:28] Return("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@sub-record-check:20] Return("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:11] Set("SIP/GV1860821xxxx-00000001", "RingGroupMethod=ringall") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [600@ext-group:12] Macro("SIP/GV1860821xxxx-00000001", "dial,30,Ttr,101") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/GV1860821xxxx-00000001", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(ALERT_INFO=)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(ALERT_INFO=)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(ALERT_INFO=)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(CHANNEL(musicclass)=)") in new stack
[2016-04-10 10:59:31] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:6] AGI("SIP/GV1860821xxxx-00000001", "dialparties.agi") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Caller ID name is 'M MATHEWSON' number is '860324xxxx'
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Added extension 101 to extension map
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Extension 101 cf is disabled
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Extension 101 do not disturb is disabled
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: dbset CALLTRACE/101 to 860324xxxx
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: dialparties.agi: Filtered ARG3: 101
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] res_agi.c: <SIP/GV1860821xxxx-00000001>AGI Script dialparties.agi completed, returning 0
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/GV1860821xxxx-00000001", "Returned from dialparties with groups to dial") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:10] Set("SIP/GV1860821xxxx-00000001", "LOOPCNT=1") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:11] Set("SIP/GV1860821xxxx-00000001", "ITER=1") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:12] Set("SIP/GV1860821xxxx-00000001", "EXTTOCALL=101") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/GV1860821xxxx-00000001", "Working with 101") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:14] Set("SIP/GV1860821xxxx-00000001", "ITER=2") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:15] GotoIf("SIP/GV1860821xxxx-00000001", "0?ndloopbegin") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:16] Macro("SIP/GV1860821xxxx-00000001", "dial-ringall-predial-hook,") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-dial:17] Dial("SIP/GV1860821xxxx-00000001", "SIP/99101&SIP/101,30,TtrM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2016-04-10 10:59:32] WARNING[5809][C-00000001] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Subscriber absent)
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] netsock2.c: Using SIP RTP TOS bits 184
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] netsock2.c: Using SIP RTP CoS mark 5
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] app_stack.c: SIP/101-00000002 Internal Gosub(func-apply-sipheaders,s,1) start
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/101-00000002", "Applying SIP Headers to channel") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/101-00000002", "SIPHEADERKEYS=") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/101-00000002", "0") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] app_while.c: Jumping to priority 7
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/101-00000002", "") in new stack
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/101-00000002'
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] app_stack.c: SIP/101-00000002 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] app_dial.c: Called SIP/101
[2016-04-10 10:59:32] VERBOSE[2785] chan_sip.c: Extension Changed 101[ext-local] new state Ringing for Notify User 105
[2016-04-10 10:59:32] VERBOSE[5809][C-00000001] app_dial.c: SIP/101-00000002 is ringing
[2016-04-10 10:59:35] VERBOSE[2785] chan_sip.c: Extension Changed 101[ext-local] new state InUse for Notify User 105
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] app_dial.c: SIP/101-00000002 answered SIP/GV1860821xxxx-00000001
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:1] Set("SIP/101-00000002", "__MACRO_RESULT=") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:2] Set("SIP/101-00000002", "CFIGNORE=") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:3] Set("SIP/101-00000002", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:4] Set("SIP/101-00000002", "FORWARD_CONTEXT=from-internal") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:5] Set("SIP/101-00000002", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:6] Macro("SIP/101-00000002", "blkvm-clr,") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/101-00000002", "SHARED(BLKVM,SIP/GV1860821xxxx-00000001)=") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-clr:2] Set("SIP/101-00000002", "GOSUB_RETVAL=") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/101-00000002", "") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:7] ExecIf("SIP/101-00000002", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=101)") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("SIP/101-00000002", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=John Doe)") in new stack
[2016-04-10 10:59:35] VERBOSE[5831][C-00000001] bridge_channel.c: Channel SIP/101-00000002 joined 'simple_bridge' basic-bridge <9c7ab17c-20c8-41c9-87ff-c0e7a643bd5b>
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] bridge_channel.c: Channel SIP/GV1860821xxxx-00000001 joined 'simple_bridge' basic-bridge <9c7ab17c-20c8-41c9-87ff-c0e7a643bd5b>
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] bridge_channel.c: Channel SIP/GV1860821xxxx-00000001 left 'simple_bridge' basic-bridge <9c7ab17c-20c8-41c9-87ff-c0e7a643bd5b>
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] app_macro.c: Spawn extension (macro-dial, s, 17) exited non-zero on 'SIP/GV1860821xxxx-00000001' in macro 'dial'
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Spawn extension (ext-group, 600, 12) exited non-zero on 'SIP/GV1860821xxxx-00000001'
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [h@ext-group:1] Macro("SIP/GV1860821xxxx-00000001", "hangupcall,") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/GV1860821xxxx-00000001", "1?theend") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Goto (macro-hangupcall,s,3)
[2016-04-10 10:59:35] VERBOSE[5831][C-00000001] bridge_channel.c: Channel SIP/101-00000002 left 'simple_bridge' basic-bridge <9c7ab17c-20c8-41c9-87ff-c0e7a643bd5b>
[2016-04-10 10:59:35] VERBOSE[2785] chan_sip.c: Extension Changed 101[ext-local] new state Idle for Notify User 105
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/GV1860821xxxx-00000001", "0?Set(CDR(recordingfile)=)") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/GV1860821xxxx-00000001", "") in new stack
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/GV1860821xxxx-00000001' in macro 'hangupcall'
[2016-04-10 10:59:35] VERBOSE[5809][C-00000001] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/GV1860821xxxx-00000001'

tm1000 · April 10, 2016, 6:23pm

Is this a Google voice trunk? If so your issue is probably Google voice and the channel not answering in the time Google voice wants it to.

necits2015 · April 11, 2016, 10:13pm

Yes it is I was using it for testing bc it was free and worked great for this purpose until the ring group issue. That would make sense considering there doesn’t seem to be any other users experiencing this problem. It’s actually a gateway through Simon telephonics (https://simonics.com/gw/) Just out of curiosity could google be blocking this on their end? Because if I set the incoming route to just an extension I can answer it with out issues.

cynjut · April 11, 2016, 10:41pm

Didn’t I read something that Google Voice was going away, or at least the Free version.

There was a stretch there last summer where everybody was having trouble with Google Voice. remember, you get what you pay for, and if you are running a business, it just doesn’t pay to go cheap on something as critical as a voice line.

Besides, there are plenty of “real” VOIP providers out there that will work with you on this kind of stuff. Getting a commercial-class provider isn’t going to be a bank-breaker - Even for incoming, you’d be looking at under $10 a month for most good providers. I recommend (in no particular order) VOIP Innovations, AlcazarNetworks, and SIPStation.

tm1000 · April 12, 2016, 12:00am

It’s been going away for two years now.

cynjut · April 12, 2016, 1:06pm

Yup - that sounds about right.

dziny · April 12, 2016, 1:13pm

I am also having problems with ring groups after last upgrade. I have upgraded from 12.0.3.2 to 12.0.3.3. (I am still on fpbx 12). Some (not all) extensions have the following issue. If I call the ring group I am getting a one way audio. If I call the extension directly audio works fine. I tried to downgrade to 12.0.3.2 and the problem is gone.

This has no connection to GV as all calls are internal in my case. Strangely, as I wrote above only some extensions are affected, others works fine. Go figure!

necits2015 · April 12, 2016, 2:38pm

Thanks for the feedback!

Yes Dave makes perfect sense. I would never use Google Voice in a production environment. Actually all my clients use analog trunks. This was just for a test box that I could bang around on and try different features, play with AGI, etc. I will stop being cheap and purchase service from a “real” provider lol

Yes I think sometime in 2015. There are some GV sip gateways out there that seemed to work but obviously there are issues.

jfinstrom · April 12, 2016, 4:46pm

From google:
Settings>Asterisk SIP Settings
2. Ensure at least one Google Voice supported CODEC is active
3. Ensure Google Voice supported CODECs are stacked above other activated CODECs
4. Click “Submit” button
5. Click “Apply Config” button
6. Enjoy Google Voice connectivity.

I don’t use google voice because working or not it violates their ToS and AUP to use it in this manner. That said I havn’t tested this and cannot verify it works.

necits2015 · April 12, 2016, 7:27pm

Thanks James. Yes putting gsm at the top of the list seems to have resolved the issue. Anyhow I’m going to be switching to a paid provider. You definitely get what you pay for and I don’t want to violate any TOS.