IVR timeout action runs long after caller hangs up

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 [[email protected]:1] Set("PJSIP/SipTrunk-00000020", "__DIRECTION=INBOUND") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:1] GotoIf("PJSIP/SipTrunk-00000020", "0?initialized") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:2] Set("PJSIP/SipTrunk-00000020", "__REC_STATUS=INITIALIZED") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:3] Set("PJSIP/SipTrunk-00000020", "NOW=1524074980") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:4] Set("PJSIP/SipTrunk-00000020", "__DAY=18") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:5] Set("PJSIP/SipTrunk-00000020", "__MONTH=04") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:6] Set("PJSIP/SipTrunk-00000020", "__YEAR=2018") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:7] Set("PJSIP/SipTrunk-00000020", "__TIMESTR=20180418-140940") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:8] Set("PJSIP/SipTrunk-00000020", "__FROMEXTEN=unknown") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:9] Set("PJSIP/SipTrunk-00000020", "__MON_FMT=wav") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/SipTrunk-00000020", "Recordings initialized") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:2] Set("PJSIP/SipTrunk-00000020", "FROMEXTEN=unknown") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:3] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:5] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:1] GotoIf("PJSIP/SipTrunk-00000020", "0?blacklisted") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:2] Set("PJSIP/SipTrunk-00000020", "CALLED_BLACKLIST=1") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:3] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:4] Set("PJSIP/SipTrunk-00000020", "__FROM_DID=+19876543210") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:5] Set("PJSIP/SipTrunk-00000020", "CDR(did)=+19876543210") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:7] Set("PJSIP/SipTrunk-00000020", "__MOHCLASS=") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:8] Ringing("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:9] Set("PJSIP/SipTrunk-00000020", "__RINGINGSENT=TRUE") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:10] Set("PJSIP/SipTrunk-00000020", "__REVERSAL_REJECT=FALSE") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:13] NoOp("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:40] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:14] Wait("PJSIP/SipTrunk-00000020", "3") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:19] NoOp("PJSIP/SipTrunk-00000020", "CallerID Entry Point") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:20] Set("PJSIP/SipTrunk-00000020", "__CRM_DIRECTION=INBOUND") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:21] Set("PJSIP/SipTrunk-00000020", "__CRM_SOURCE=+10123456789") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] Set("PJSIP/SipTrunk-00000020", "INVALID_LOOPCOUNT=0") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:4] Set("PJSIP/SipTrunk-00000020", "__IVR_RETVM=") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:5] GotoIf("PJSIP/SipTrunk-00000020", "0?skip") in new stack
[2018-04-18 14:09:43] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:6] Answer("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:44] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:7] Wait("PJSIP/SipTrunk-00000020", "1") in new stack
[2018-04-18 14:09:45] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] GotoIf("PJSIP/SipTrunk-00000020", "0?cid") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:2] PlayTones("PJSIP/SipTrunk-00000020", "ring") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:3] Progress("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:4] Macro("PJSIP/SipTrunk-00000020", "user-callerid,") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:2] Set("PJSIP/SipTrunk-00000020", "AMPUSER=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:3] GotoIf("PJSIP/SipTrunk-00000020", "0?report") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:5] Set("PJSIP/SipTrunk-00000020", "AMPUSER=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:6] GotoIf("PJSIP/SipTrunk-00000020", "0?limit") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:7] Set("PJSIP/SipTrunk-00000020", "AMPUSERCIDNAME=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:19] GotoIf("PJSIP/SipTrunk-00000020", "0?continue") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:20] Set("PJSIP/SipTrunk-00000020", "__TTL=64") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:37] Set("PJSIP/SipTrunk-00000020", "CALLERID(number)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:38] Set("PJSIP/SipTrunk-00000020", "CALLERID(name)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:39] GotoIf("PJSIP/SipTrunk-00000020", "0?cnum") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:40] Set("PJSIP/SipTrunk-00000020", "CDR(cnam)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:41] Set("PJSIP/SipTrunk-00000020", "CDR(cnum)=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:42] Set("PJSIP/SipTrunk-00000020", "CHANNEL(language)=en") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:5] Macro("PJSIP/SipTrunk-00000020", "blkvm-setifempty,") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:6] Set("PJSIP/SipTrunk-00000020", "GOSUB_RETVAL=TRUE") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:7] MacroExit("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:9] Set("PJSIP/SipTrunk-00000020", "RRNODEST=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:10] Set("PJSIP/SipTrunk-00000020", "__NODEST=300") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:12] Set("PJSIP/SipTrunk-00000020", "__PICKUPMARK=300") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:10] NoOp("PJSIP/SipTrunk-00000020", "Recordings initialized") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:19] Gosub("PJSIP/SipTrunk-00000020", "recordcheck,1(dontcare,rg,300)") in new stack

Second half of the log:

[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:3] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:20] Return("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:14] Set("PJSIP/SipTrunk-00000020", "RingGroupMethod=memoryhunt") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:15] Set("PJSIP/SipTrunk-00000020", "__ALT_CONFIRM_MSG=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:2] Set("PJSIP/SipTrunk-00000020", "__CRM_SOURCE=+10123456789") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:28] Set("PJSIP/SipTrunk-00000020", "HuntLoop=0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:33] Set("PJSIP/SipTrunk-00000020", "HuntMember=HuntMember0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:41] Set("PJSIP/SipTrunk-00000020", "CTLoop=0") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:42] GotoIf("PJSIP/SipTrunk-00000020", "0?huntstart") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:43] Set("PJSIP/SipTrunk-00000020", "CT_EXTEN=320") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:44] Set("PJSIP/SipTrunk-00000020", "__EXTTOCALL=320") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]:46] Set("PJSIP/SipTrunk-00000020", "CTLoop=1") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:48] NoOp("PJSIP/SipTrunk-00000020", "Hunt Dial Start") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] MacroExit("PJSIP/SipTrunk-00000020", "") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:3] Set("PJSIP/320-00000021", "SIPHEADERKEYS=") in new stack
[2018-04-18 14:09:59] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:2] NoOp("PJSIP/320-00000021", "HANGUP CAUSE: 0") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] Macro("PJSIP/SipTrunk-00000020", "hangupcall,") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:2] NoOp("PJSIP/SipTrunk-00000020", "HANGUP CAUSE: 18") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:5] GotoIf("PJSIP/SipTrunk-00000020", "0?return") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]:6] Set("PJSIP/SipTrunk-00000020", "__CRM_HANGUP=1") in new stack
[2018-04-18 14:10:15] VERBOSE[6118][C-0000000f] pbx.c: Executing [[email protected]: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 [[email protected]: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=

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