Inbound Calls Don't Hang Up

johnmillington · October 18, 2018, 1:48pm

Hi All,

i’m sure this is a common issue when freshly setting up a phone system, however, I can’t seem to find a resolution.

I’m using freePBX with Yealink phones and outbound calls work fine. There is an issue over all with inbound calls which the following symptoms are happening.

Inbound calls hang up on the phone after 64 seconds every time but the callers end doesn’t hang up. during the 64 seconds, the call is perfect.

When I make and inbound call and hang up within the 64 seconds, the callers end still doesn’t hang up.

To confirm, outbound calls work fine. I hang up the call ends on both ends.

I’m using a Simwood and PJSIP trunk on the phone system.
All firewall rules are correct. i have checked and checked.
Firewall is PFsense pysical firewall on Netgate hardware.
I have checked all the codec’s and they are support by Simwood.
Codec used are g722 and opus
PBX Firmware 12.7.5
all modules up to date.

i’m at a complete loss with this one.

Thanks all

stom · October 18, 2018, 2:43pm

What do the logs at 64 secs say? What is logged as disconnect reason?
You can always take a diagnostics/capture from pfsense and analyze it e.g with wireshark.

johnmillington · October 18, 2018, 3:52pm

this is what the logs show from the call connecting to disconnecting

[2018-10-18 15:14:27] VERBOSE[62880][C-00000020] bridge_channel.c: Channel PJSIP/202-00000041 joined ‘simple_bridge’ basic-bridge <b1e3c2ff-d328-4f82-9975-228a43b3dbd4>
[2018-10-18 15:14:27] VERBOSE[62877][C-00000020] bridge_channel.c: Channel PJSIP/Simwood-Trunk-PJSIP-00000040 joined ‘simple_bridge’ basic-bridge <b1e3c2ff-d328-4f82-9975-228a43b3dbd4>
[2018-10-18 15:15:31] VERBOSE[62877][C-00000020] bridge_channel.c: Channel PJSIP/Simwood-Trunk-PJSIP-00000040 left ‘simple_bridge’ basic-bridge <b1e3c2ff-d328-4f82-9975-228a43b3dbd4>
[2018-10-18 15:15:31] VERBOSE[62880][C-00000020] bridge_channel.c: Channel PJSIP/202-00000041 left ‘simple_bridge’ basic-bridge <b1e3c2ff-d328-4f82-9975-228a43b3dbd4>

PitzKey · October 18, 2018, 6:24pm

Is this a outbound or inbound call?
From this log it seems that both got disconnected at the same time.

I wanted to jump and say that this is a RTP issue, but from the 4 lines you posted it doesn’t indicate so. Can you post a full call log?

Are the phones and the PBX on the same network?
What ports do you have open?
Finally, if you search here, you should be able to find many posts regarding using pfsense + FreePBX.

Henry_power · October 22, 2018, 9:24pm

If you are sending the incoming call to IVR , set Retries to 3. This worked for me, The IVR was going to a loop

johnmillington · October 29, 2018, 4:29pm

It’s inbound calls online that have the problem and I’m not using an IVR, this is just direct to the extension. I have also tried multiple extension and currently have a queue pointing at a dead extension which gets the same (hold music drops after 64 seconds).

Here is the full long from the start of the call to the end

[2018-10-29 16:13:46] VERBOSE[214487] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘88.##.##.##’
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:1] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__DIRECTION=INBOUND”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:2] Gosub(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “sub-record-check,s,1(in,441234567890,dontcare)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?initialized”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__REC_STATUS=INITIALIZED”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “NOW=1540829626”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__DAY=29”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__MONTH=10”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__YEAR=2018”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__TIMESTR=20181029-161346”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__FROMEXTEN=unknown”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__MON_FMT=wav”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Recordings initialized”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(ARG3=dontcare)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “REC_POLICY_MODE_SAVE=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “2?checkaction”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?sub-record-check,in,1”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (sub-record-check,in,1)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [in@sub-record-check:1] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Inbound Recording Check to 441234567890”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [in@sub-record-check:2] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “FROMEXTEN=unknown”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [in@sub-record-check:3] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “11?Set(FROMEXTEN=07722000000)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [in@sub-record-check:4] Gosub(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “recordcheck,1(dontcare,in,441234567890)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Starting recording check against dontcare”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “dontcare”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [in@sub-record-check:5] Return(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:3] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CHANNEL(tonezone)=uk”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:4] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__FROM_DID=441234567890”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:5] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “returnhere=1”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:6] Gosub(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “app-blacklist-check,s,1()”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?blacklisted”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@app-blacklist-check:2] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CALLED_BLACKLIST=1”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@app-blacklist-check:3] Return(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:7] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CDR(did)=441234567890”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:8] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:9] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0 ?Set(CALLERID(name)=07722000000)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:10] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__MOHCLASS=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:11] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__REVERSAL_REJECT=FALSE”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:12] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?post-reverse-charge”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (from-trunk,441234567890,14)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:14] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:15] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:16] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:17] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:18] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:19] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CallerID Entry Point”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:20] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__CRM_DIRECTION=INBOUND”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:21] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__CRM_SOURCE=07722000000”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:22] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__CRM_LINKEDID=1540829626.39”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:23] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [441234567890@from-trunk:24] Goto(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “ext-queues,400,1”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (ext-queues,400,1)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:1] Macro(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “user-callerid,”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:1] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “TOUCH_MONITOR=1540829626.39”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:2] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “AMPUSER=07722000000”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?report”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(REALCALLERIDNUM=07722000000)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:5] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “AMPUSER=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?limit”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:7] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “AMPUSERCIDNAME=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?report”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (macro-user-callerid,s,16)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Macro Depth is 1”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?report2:macroerror”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:18] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?continue”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:19] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:20] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__TTL=64”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:21] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?continue”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:37] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CALLERID(number)=07722000000”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:38] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CALLERID(name)=07722000000”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?cnum”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:40] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CDR(cnam)=07722000000”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:41] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CDR(cnum)=07722000000”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-user-callerid:42] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “CHANNEL(language)=en”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:2] Answer(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:3] Macro(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “blkvm-set,reset”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-blkvm-set:1] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(__BLKVM_CHANNEL=PJSIP/Simwood-PJSIPTrunk-0000001d)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-blkvm-set:2] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “SHARED(BLKVM,PJSIP/Simwood-PJSIPTrunk-0000001d)=TRUE”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-blkvm-set:3] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “GOSUB_RETVAL=TRUE”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-blkvm-set:4] MacroExit(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:4] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(_DIAL_OPTIONS=HhTtrM(auto-blkvm))”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:5] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__NODEST=400”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:6] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QCIDPP=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:7] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_CIDPP=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:8] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Macro(prepend-cid,)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:9] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QAINFO=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:10] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_AINFO=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:11] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__RVOL_MODE=dontcare”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:12] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(__ALERT_INFO=)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:13] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QJOINMSG=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:14] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_JOINMSG=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:15] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QCANCELMISSED=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:16] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QRETRY=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:17] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_RETRY=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:18] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QOPTIONS=t”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:19] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_OPTIONS=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:20] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QGOSUB=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:21] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_GOSUB=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:22] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QAGI=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:23] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_AGI=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:24] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QRULE=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:25] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_RULE=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:26] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QPOSITION=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:27] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_POSITION=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:28] Gosub(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “sub-record-check,s,1(q,400,dontcare)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “11?initialized”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (sub-record-check,s,10)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Recordings initialized”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(ARG3=dontcare)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “REC_POLICY_MODE_SAVE=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?checkaction”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?sub-record-check,q,1”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:18] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Generic q Recording Check - 07722000000 400”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:19] Gosub(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “recordcheck,1(dontcare,q,400)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Starting recording check against dontcare”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “dontcare”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@sub-record-check:20] Return(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:29] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__SIGNORE=TRUE”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:30] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__QC_CONFIRM=0”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:31] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?QVQANNOUNCE:NOQVQANNOUNCE”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (ext-queues,400,36)
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:36] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_CONFIRMMSG=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:37] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Playback(, )”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:38] QueueLog(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “400,1540829626.39,NONE,DID,441234567890”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:39] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QAANNOUNCE=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:40] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_AANNOUNCE=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:41] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QMOH=default”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:42] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_MOH=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:43] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(__MOHCLASS=default)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:44] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?Set(CHANNEL(musicclass)=default)”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:45] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QMAXWAIT=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:46] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “VQ_MAXWAIT=”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:47] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QUEUENUM=400”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:48] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “QUEUEJOINTIME=1540829626”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] pbx.c: Executing [400@ext-queues:49] Queue(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “400,t,”) in new stack
[2018-10-29 16:13:46] VERBOSE[2440][C-0000000e] res_musiconhold.c: Started music on hold, class ‘default’, on channel ‘PJSIP/Simwood-PJSIPTrunk-0000001d’
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] res_musiconhold.c: Stopped music on hold on PJSIP/Simwood-PJSIPTrunk-0000001d
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx.c: Spawn extension (ext-queues, 400, 49) exited non-zero on ‘PJSIP/Simwood-PJSIPTrunk-0000001d’
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx.c: Executing [h@ext-queues:1] Macro(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “hangupcall,”) in new stack
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “1?theend”) in new stack
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(CDR(recordingfile)=)”) in new stack
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, " monior file= ") in new stack
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-hangupcall:5] AGI(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “attendedtransfer-rec-restart.php,”) in new stack
[2018-10-29 16:14:50] VERBOSE[2440][C-0000000e] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] res_agi.c: <PJSIP/Simwood-PJSIPTrunk-0000001d>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@macro-hangupcall:6] Hangup(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘PJSIP/Simwood-PJSIPTrunk-0000001d’ in macro ‘hangupcall’
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Spawn extension (ext-queues, h, 1) exited non-zero on ‘PJSIP/Simwood-PJSIPTrunk-0000001d’
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] app_stack.c: PJSIP/Simwood-PJSIPTrunk-0000001d Internal Gosub(crm-hangup,s,1) start
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:1] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “Sending Hangup to CRM”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:2] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “HANGUP CAUSE: 18”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:3] ExecIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:4] NoOp(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “MASTER CHANNEL: 1540829626.39 = 1540829626.39”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:5] GotoIf(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “0?return”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:6] Set(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “__CRM_HANGUP=1”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:7] AGI(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “sangomacrm.agi”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] res_agi.c: <PJSIP/Simwood-PJSIPTrunk-0000001d>AGI Script sangomacrm.agi completed, returning 0
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] pbx.c: Executing [s@crm-hangup:8] Return(“PJSIP/Simwood-PJSIPTrunk-0000001d”, “”) in new stack
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] app_stack.c: Spawn extension (ext-queues, h, 1) exited non-zero on ‘PJSIP/Simwood-PJSIPTrunk-0000001d’
[2018-10-29 16:14:51] VERBOSE[2440][C-0000000e] app_stack.c: PJSIP/Simwood-PJSIPTrunk-0000001d Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

cynjut · October 30, 2018, 2:28pm

After this, the system tries at least three different ways to hang up your call.

Sounds like it’s time for a SIP DEBUG and (perhaps) a quick call to your ITSP. Your tone-set is setup for UK, so there might be an issue there that your ITSP is having trouble with.

johnmillington · October 30, 2018, 3:47pm

this might sound daft but what do you mean by “SIP DEBUG”? I have tried typing “sip set debug on” into the cli but the command isn’t recognised. I have also created a new logging set with all options on and I dont get anything solid between the hold music starting and stopping.

cynjut · October 30, 2018, 5:24pm

As always, the Wiki contains a lot of details that can come in handy.

https://wiki.freepbx.org/display/SUP/Providing+Great+Debug

The first question, of course, is if you are using Chan_SIP or PJ-SIP. The commands for debugging these are different. Once you’ve reviewed the Wiki and determined your primary channel driver, the answer to your question will be complete, and we can get back to solving your hang up problem.

johnmillington · November 6, 2018, 12:38pm

The stange thing is, i’ve seen many articles like this including this one but all the commands don’t work on the version on FreePBX i’m running. just get “no such command”

cynjut · November 6, 2018, 3:15pm

Tell us what you are doing, not that what you are doing isn’t working.

It’s the difference between “When I’m driving something makes a funny noise” and “The car knocks when I turn left”.

system · November 13, 2018, 3:35pm

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