IVR timeout action runs long after caller hangs up

stefanwild · April 18, 2018, 8:04pm

We have a recent FreePBX installation, hooked up to an SIP trunk via pjsip. Our IVR is set to call a Ring Group (a simple memoryhunt on 3 extensions) on timeout. When an external caller hangs up during the announcement or during the following waiting period, the Ring Group still gets called. When I answer one of those “zombie” calls, there’s just silence.

However, when a call is connected (extension to external, both incoming and outgoing) and the external party hangs up, the call is properly terminated right away. That means, there seems to be no general issue recognizing when an external caller hangs up.

My best guess is it has to do with the IVR waiting for a touchtone, but I just don’t have the experience to dig into it deeper. Any help is appreciated.

Thanks,
Stefan

Current PBX Version: 14.0.2.10
Current System Version: 12.7.4-1803-1.sng7
Current Asterisk Version: 13.19.1

First half of full log of a test call (hung up within 2 seconds after the call was established) with IPs anonymized to X.X.X.X, external caller to +19876543210, PBX number to +10123456789:

[2018-04-18 14:09:40] VERBOSE[15414] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'X.X.X.X'
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:1] Set("PJSIP/SipTrunk-00000020", "__DIRECTION=INBOUND") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:2] Gosub("PJSIP/SipTrunk-00000020", "sub-record-check,s,1(in,+19876543210,dontcare)") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/SipTrunk-00000020", "0?initialized") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/SipTrunk-00000020", "__REC_STATUS=INITIALIZED") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/SipTrunk-00000020", "NOW=1524074980") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/SipTrunk-00000020", "__DAY=18") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/SipTrunk-00000020", "__MONTH=04") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/SipTrunk-00000020", "__YEAR=2018") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/SipTrunk-00000020", "__TIMESTR=20180418-140940") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/SipTrunk-00000020", "__FROMEXTEN=unknown") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/SipTrunk-00000020", "__MON_FMT=wav") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/SipTrunk-00000020", "Recordings initialized") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(ARG3=dontcare)") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/SipTrunk-00000020", "REC_POLICY_MODE_SAVE=") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(REC_STATUS=NO)") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/SipTrunk-00000020", "2?checkaction") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/SipTrunk-00000020", "1?sub-record-check,in,1") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (sub-record-check,in,1)
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [in@sub-record-check:1] NoOp("PJSIP/SipTrunk-00000020", "Inbound Recording Check to +19876543210") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [in@sub-record-check:2] Set("PJSIP/SipTrunk-00000020", "FROMEXTEN=unknown") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [in@sub-record-check:3] ExecIf("PJSIP/SipTrunk-00000020", "12?Set(FROMEXTEN=+10123456789)") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [in@sub-record-check:4] Gosub("PJSIP/SipTrunk-00000020", "recordcheck,1(dontcare,in,+19876543210)") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/SipTrunk-00000020", "Starting recording check against dontcare") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/SipTrunk-00000020", "dontcare") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [in@sub-record-check:5] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:3] Gosub("PJSIP/SipTrunk-00000020", "app-blacklist-check,s,1()") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("PJSIP/SipTrunk-00000020", "0?blacklisted") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/SipTrunk-00000020", "CALLED_BLACKLIST=1") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:4] Set("PJSIP/SipTrunk-00000020", "__FROM_DID=+19876543210") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:5] Set("PJSIP/SipTrunk-00000020", "CDR(did)=+19876543210") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:6] ExecIf("PJSIP/SipTrunk-00000020", "1 ?Set(CALLERID(name)=+10123456789)") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:7] Set("PJSIP/SipTrunk-00000020", "__MOHCLASS=") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:8] Ringing("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:9] Set("PJSIP/SipTrunk-00000020", "__RINGINGSENT=TRUE") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:10] Set("PJSIP/SipTrunk-00000020", "__REVERSAL_REJECT=FALSE") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:11] GotoIf("PJSIP/SipTrunk-00000020", "1?post-reverse-charge") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (from-pstn,+19876543210,13)
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:13] NoOp("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:14] Wait("PJSIP/SipTrunk-00000020", "3") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:15] Set("PJSIP/SipTrunk-00000020", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:16] Set("PJSIP/SipTrunk-00000020", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:17] Set("PJSIP/SipTrunk-00000020", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:18] Set("PJSIP/SipTrunk-00000020", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:19] NoOp("PJSIP/SipTrunk-00000020", "CallerID Entry Point") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:20] Set("PJSIP/SipTrunk-00000020", "__CRM_DIRECTION=INBOUND") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:21] Set("PJSIP/SipTrunk-00000020", "__CRM_SOURCE=+10123456789") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:22] Set("PJSIP/SipTrunk-00000020", "__CRM_LINKEDID=1524074980.24092") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:23] ExecIf("PJSIP/SipTrunk-00000020", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [+19876543210@from-pstn:24] Goto("PJSIP/SipTrunk-00000020", "ivr-1,s,1") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (ivr-1,s,1)
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:1] Set("PJSIP/SipTrunk-00000020", "INVALID_LOOPCOUNT=0") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:2] Set("PJSIP/SipTrunk-00000020", "_IVR_CONTEXT_ivr-1=") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:3] Set("PJSIP/SipTrunk-00000020", "_IVR_CONTEXT=ivr-1") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:4] Set("PJSIP/SipTrunk-00000020", "__IVR_RETVM=") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:5] GotoIf("PJSIP/SipTrunk-00000020", "0?skip") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:6] Answer("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:44] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:7] Wait("PJSIP/SipTrunk-00000020", "1") in new stack
[2018-04-18 14:09:45] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:8] Set("PJSIP/SipTrunk-00000020", "IVR_MSG=custom/ivr-main") in new stack
[2018-04-18 14:09:45] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:9] Set("PJSIP/SipTrunk-00000020", "TIMEOUT(digit)=3") in new stack
[2018-04-18 14:09:45] VERBOSE[6118][C-0000000f] func_timeout.c: Digit timeout set to 3.000
[2018-04-18 14:09:45] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:10] ExecIf("PJSIP/SipTrunk-00000020", "1?Background(custom/ivr-main)") in new stack
[2018-04-18 14:09:45] VERBOSE[6118][C-0000000f] file.c: <PJSIP/SipTrunk-00000020> Playing 'custom/ivr-main.slin' (language 'en')
[2018-04-18 14:09:54] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@ivr-1:11] WaitExten("PJSIP/SipTrunk-00000020", "5,") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Timeout on PJSIP/SipTrunk-00000020, going to 't'
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [t@ivr-1:1] Goto("PJSIP/SipTrunk-00000020", "ext-group,300,1") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (ext-group,300,1)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:1] GotoIf("PJSIP/SipTrunk-00000020", "0?cid") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:2] PlayTones("PJSIP/SipTrunk-00000020", "ring") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:3] Progress("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:4] Macro("PJSIP/SipTrunk-00000020", "user-callerid,") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/SipTrunk-00000020", "TOUCH_MONITOR=1524074980.24092") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/SipTrunk-00000020", "AMPUSER=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/SipTrunk-00000020", "0?report") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/SipTrunk-00000020", "1?Set(REALCALLERIDNUM=+10123456789)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/SipTrunk-00000020", "AMPUSER=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/SipTrunk-00000020", "0?limit") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/SipTrunk-00000020", "AMPUSERCIDNAME=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("PJSIP/SipTrunk-00000020", "1?report") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-user-callerid,s,16)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:16] NoOp("PJSIP/SipTrunk-00000020", "Macro Depth is 1") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/SipTrunk-00000020", "1?report2:macroerror") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("PJSIP/SipTrunk-00000020", "0?continue") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:20] Set("PJSIP/SipTrunk-00000020", "__TTL=64") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("PJSIP/SipTrunk-00000020", "1?continue") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/SipTrunk-00000020", "CALLERID(number)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:38] Set("PJSIP/SipTrunk-00000020", "CALLERID(name)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("PJSIP/SipTrunk-00000020", "0?cnum") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/SipTrunk-00000020", "CDR(cnam)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/SipTrunk-00000020", "CDR(cnum)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-user-callerid:42] Set("PJSIP/SipTrunk-00000020", "CHANNEL(language)=en") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:5] Macro("PJSIP/SipTrunk-00000020", "blkvm-setifempty,") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("PJSIP/SipTrunk-00000020", "1?init") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-blkvm-setifempty,s,4)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("PJSIP/SipTrunk-00000020", "__BLKVM_CHANNEL=PJSIP/SipTrunk-00000020") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("PJSIP/SipTrunk-00000020", "SHARED(BLKVM,PJSIP/SipTrunk-00000020)=TRUE") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("PJSIP/SipTrunk-00000020", "GOSUB_RETVAL=TRUE") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:6] GotoIf("PJSIP/SipTrunk-00000020", "1?skipov") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (ext-group,300,9)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:9] Set("PJSIP/SipTrunk-00000020", "RRNODEST=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:10] Set("PJSIP/SipTrunk-00000020", "__NODEST=300") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:11] GosubIf("PJSIP/SipTrunk-00000020", "0?sub-rgsetcid,s,1()") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:12] Set("PJSIP/SipTrunk-00000020", "__PICKUPMARK=300") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:13] Gosub("PJSIP/SipTrunk-00000020", "sub-record-check,s,1(rg,300,dontcare)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/SipTrunk-00000020", "12?initialized") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (sub-record-check,s,10)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/SipTrunk-00000020", "Recordings initialized") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(ARG3=dontcare)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/SipTrunk-00000020", "REC_POLICY_MODE_SAVE=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(REC_STATUS=NO)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/SipTrunk-00000020", "2?checkaction") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/SipTrunk-00000020", "0?sub-record-check,rg,1") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:18] NoOp("PJSIP/SipTrunk-00000020", "Generic rg Recording Check - +10123456789 300") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:19] Gosub("PJSIP/SipTrunk-00000020", "recordcheck,1(dontcare,rg,300)") in new stack

stefanwild · April 18, 2018, 8:10pm

Second half of the log:

[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/SipTrunk-00000020", "Starting recording check against dontcare") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/SipTrunk-00000020", "dontcare") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@sub-record-check:20] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:14] Set("PJSIP/SipTrunk-00000020", "RingGroupMethod=memoryhunt") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:15] Set("PJSIP/SipTrunk-00000020", "__ALT_CONFIRM_MSG=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:16] GotoIf("PJSIP/SipTrunk-00000020", "0?RGVQANNOUNCE:NORGVQANNOUNCE") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (ext-group,300,19)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [300@ext-group:19] Macro("PJSIP/SipTrunk-00000020", "dial,20,HhTtr,320-321-322") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:1] NoOp("PJSIP/SipTrunk-00000020", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:2] Set("PJSIP/SipTrunk-00000020", "__CRM_SOURCE=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:3] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(ALERT_INFO=)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:4] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(ALERT_INFO=)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:5] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(ALERT_INFO=)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:6] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(CHANNEL(musicclass)=)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:7] AGI("PJSIP/SipTrunk-00000020", "dialparties.agi") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Caller ID name is '+10123456789' number is '+10123456789'
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: CW Ignore is:
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: CF Ignore is:
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: CW IN_USE/BUSY is: 1
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Methodology of ring is  'memoryhunt'
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Added extension 320 to extension map
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Added extension 321 to extension map
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Added extension 322 to extension map
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Extension 320 cf is disabled
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Extension 321 cf is disabled
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Extension 322 cf is disabled
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Extension 320 do not disturb is disabled
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Extension 321 do not disturb is disabled
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Extension 322 do not disturb is disabled
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Discovered PJSIP Endpoint PJSIP/320
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Ended up with real PJSIP Dial string PJSIP/320/sip:[email protected]:5060
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Discovered PJSIP Endpoint PJSIP/321
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Ended up with real PJSIP Dial string PJSIP/321/sip:[email protected]:5060
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Discovered PJSIP Endpoint PJSIP/322
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Ended up with real PJSIP Dial string PJSIP/322/sip:[email protected]:5060
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: Filtered ARG3: 320-321-322
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: RVOL_MODE ''
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: RVOL is:
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: dialparties.agi: RVOLPARENT is:
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] res_agi.c: <PJSIP/SipTrunk-00000020>AGI Script dialparties.agi completed, returning 0
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:27] NoOp("PJSIP/SipTrunk-00000020", "Returned from dialparties with 3 hunt members to dial") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:28] Set("PJSIP/SipTrunk-00000020", "HuntLoop=0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:29] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(HuntMembers=0)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:30] GotoIf("PJSIP/SipTrunk-00000020", "1?a30") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-dial,s,33)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:33] Set("PJSIP/SipTrunk-00000020", "HuntMember=HuntMember0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:34] GotoIf("PJSIP/SipTrunk-00000020", "0?a32:a35") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-dial,s,40)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:40] GotoIf("PJSIP/SipTrunk-00000020", "1?a36:a50") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-dial,s,41)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:41] Set("PJSIP/SipTrunk-00000020", "CTLoop=0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:42] GotoIf("PJSIP/SipTrunk-00000020", "0?huntstart") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:43] Set("PJSIP/SipTrunk-00000020", "CT_EXTEN=320") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:44] Set("PJSIP/SipTrunk-00000020", "__EXTTOCALL=320") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:45] Set("PJSIP/SipTrunk-00000020", "DB(CALLTRACE/320)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:46] Set("PJSIP/SipTrunk-00000020", "CTLoop=1") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:47] Goto("PJSIP/SipTrunk-00000020", "s,a37") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-dial,s,42)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:42] GotoIf("PJSIP/SipTrunk-00000020", "1?huntstart") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-dial,s,48)
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:48] NoOp("PJSIP/SipTrunk-00000020", "Hunt Dial Start") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:49] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:50] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:51] Macro("PJSIP/SipTrunk-00000020", "dial-hunt-predial-hook,") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial-hunt-predial-hook:1] MacroExit("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-dial:52] Dial("PJSIP/SipTrunk-00000020", "PJSIP/320/sip:[email protected]:5060,20,HhtrM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] app_stack.c: PJSIP/320-00000021 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/320-00000021", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/320-00000021", "Applying SIP Headers to channel") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/320-00000021", "SIPHEADERKEYS=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@func-apply-sipheaders:4] While("PJSIP/320-00000021", "0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] app_while.c: Jumping to priority 8
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@func-apply-sipheaders:9] Return("PJSIP/320-00000021", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] app_stack.c: Spawn extension (from-internal, 300, 1) exited non-zero on 'PJSIP/320-00000021'
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] app_stack.c: PJSIP/320-00000021 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] app_dial.c: Called PJSIP/320/sip:[email protected]:5060
[2018-04-18 14:09:59] VERBOSE[21032] netsock2.c: Using SIP RTP Audio TOS bits 184
[2018-04-18 14:09:59] VERBOSE[21032] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2018-04-18 14:09:59] VERBOSE[21032] netsock2.c: Using SIP RTP Audio CoS mark 5
[2018-04-18 14:09:59] VERBOSE[21032] netsock2.c: Using SIP RTP Video TOS bits 136
[2018-04-18 14:09:59] VERBOSE[21032] netsock2.c: Using SIP RTP Video TOS bits 136 in TCLASS field.
[2018-04-18 14:09:59] VERBOSE[21032] netsock2.c: Using SIP RTP Video CoS mark 4
[2018-04-18 14:10:00] VERBOSE[6118][C-0000000f] app_dial.c: PJSIP/320-00000021 is ringing
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] app_stack.c: PJSIP/320-00000021 Internal Gosub(crm-hangup,s,1) start
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/320-00000021", "Sending Hangup to CRM") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/320-00000021", "HANGUP CAUSE: 0") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/320-00000021", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/320-00000021", "MASTER CHANNEL: 1524074999.24093 = 1524074980.24092") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/320-00000021", "1?return") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (crm-hangup,s,8)
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/320-00000021", "") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] app_stack.c: Spawn extension (from-internal, 300, 1) exited non-zero on 'PJSIP/320-00000021'
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] app_stack.c: PJSIP/320-00000021 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] app_macro.c: Spawn extension (macro-dial, s, 52) exited non-zero on 'PJSIP/SipTrunk-00000020' in macro 'dial'
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Spawn extension (ext-group, 300, 19) exited non-zero on 'PJSIP/SipTrunk-00000020'
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [h@ext-group:1] Macro("PJSIP/SipTrunk-00000020", "hangupcall,") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/SipTrunk-00000020", "1?theend") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(CDR(recordingfile)=)") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/SipTrunk-00000020", "PJSIP/320-00000021 monior file= ") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-hangupcall:5] AGI("PJSIP/SipTrunk-00000020", "attendedtransfer-rec-restart.php,PJSIP/320-00000021,") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] res_agi.c: <PJSIP/SipTrunk-00000020>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@macro-hangupcall:6] Hangup("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'PJSIP/SipTrunk-00000020' in macro 'hangupcall'
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'PJSIP/SipTrunk-00000020'
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] app_stack.c: PJSIP/SipTrunk-00000020 Internal Gosub(crm-hangup,s,1) start
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/SipTrunk-00000020", "Sending Hangup to CRM") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/SipTrunk-00000020", "HANGUP CAUSE: 18") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/SipTrunk-00000020", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/SipTrunk-00000020", "MASTER CHANNEL: 1524074980.24092 = 1524074980.24092") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/SipTrunk-00000020", "0?return") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/SipTrunk-00000020", "__CRM_HANGUP=1") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/SipTrunk-00000020", "sangomacrm.agi") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-04-18 14:10:16] VERBOSE[6118][C-0000000f] res_agi.c: <PJSIP/SipTrunk-00000020>AGI Script sangomacrm.agi completed, returning 0
[2018-04-18 14:10:16] VERBOSE[6118][C-0000000f] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:10:16] VERBOSE[6118][C-0000000f] app_stack.c: Spawn extension (ext-group, h, 1) exited non-zero on 'PJSIP/SipTrunk-00000020'
[2018-04-18 14:10:16] VERBOSE[6118][C-0000000f] app_stack.c: PJSIP/SipTrunk-00000020 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

stefanwild · April 18, 2018, 8:26pm

And now, of course, it seems like the problem vanished, just as I was going to log and post the pjsip history.