Inbound Call terminates after 30 Seconds over internet

ansxley · November 29, 2021, 1:28pm

I have set up Freepbx 14.0.16.11, and I am using PFSense firewall.

I am using a Sip app (ext 399) over the internet to connect to the pabx and call a local extension (210) , through PFsense firewall.

I ran a debug and got the below output after the call is established. The unusual thing is that the call cuts only when call originates from ext 399, and not the other way round.

[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] bridge_channel.c: Channel PJSIP/399-0000046c left 'simple_bridge' basic-bridge <2f73f768-6e12-4561-b317-00b9e6da317a>
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] app_macro.c: Spawn extension (macro-dial-one, s, 62) exited non-zero on 'PJSIP/399-0000046c' in macro 'dial-one'
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] app_macro.c: Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'PJSIP/399-0000046c' in macro 'exten-vm'
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Spawn extension (ext-local, 210, 3) exited non-zero on 'PJSIP/399-0000046c'
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/399-0000046c", "hangupcall,") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/399-0000046c", "1?theend") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2021-11-23 16:52:06] VERBOSE[2813][C-000003d2] bridge_channel.c: Channel PJSIP/210-0000046d left 'simple_bridge' basic-bridge <2f73f768-6e12-4561-b317-00b9e6da317a>
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/399-0000046c", "0?Set(CDR(recordingfile)=)") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/399-0000046c", "PJSIP/210-0000046d montior file= /var/spool/asterisk/monitor/2021/11/23/internal-210-399-20211123-165129-1637679089.1892.wav") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [s@macro-hangupcall:5] GotoIf("PJSIP/399-0000046c", "0?skipagi") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [s@macro-hangupcall:6] AGI("PJSIP/399-0000046c", "attendedtransfer-rec-restart.php,PJSIP/210-0000046d,/var/spool/asterisk/monitor/2021/11/23/internal-210-399-20211123-165129-1637679089.1892.wav") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] res_agi.c: <PJSIP/399-0000046c>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Executing [s@macro-hangupcall:7] Hangup("PJSIP/399-0000046c", "") in new stack
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'PJSIP/399-0000046c' in macro 'hangupcall'
[2021-11-23 16:52:06] VERBOSE[2806][C-000003d2] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/399-0000046c'
[2021-11-23 16:52:06] VERBOSE[2807][C-000003d2] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2021-11-23 16:52:06] VERBOSE[2807][C-000003d2] app_mixmonitor.c: End MixMonitor Recording PJSIP/399-0000046c

I did another test from extension 398 (over internet) to a fixed line through the PRI line, shown below.

Note: I have sanitized the log a bit

[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] bridge_channel.c: Channel PJSIP/398-000004a3 left 'simple_bridge' basic-bridge <1a1a125e-32f2-453b-a37d-adfa427bd99c>
[2021-11-24 00:25:51] VERBOSE[9022][C-000003ff] bridge_channel.c: Channel DAHDI/i1/14243-316 left 'simple_bridge' basic-bridge <1a1a125e-32f2-453b-a37d-adfa427bd99c>
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] app_macro.c: Spawn extension (macro-dialout-trunk, s, 35) exited non-zero on 'PJSIP/398-000004a3' in macro 'dialout-trunk'
[2021-11-24 00:25:51] VERBOSE[9022][C-000003ff] chan_dahdi.c: Hungup 'DAHDI/i1/14243-316'
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Spawn extension (restrictedroute-c81e728d9d4c2f636f067f89cc14862c, 93114243, 14) exited non-zero on 'PJSIP/398-000004a3'
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [h@restrictedroute-c81e728d9d4c2f636f067f89cc14862c:1] Hangup("PJSIP/398-000004a3", "") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Spawn extension (restrictedroute-c81e728d9d4c2f636f067f89cc14862c, h, 1) exited non-zero on 'PJSIP/398-000004a3'
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] app_stack.c: PJSIP/398-000004a3 Internal Gosub(crm-hangup,s,1) start
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/398-000004a3", "Sending Hangup to CRM") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/398-000004a3", "HANGUP CAUSE: 16") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/398-000004a3", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/398-000004a3", "MASTER CHANNEL: 1637706303.1976 = 1637706303.1976") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/398-000004a3", "0?return") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/398-000004a3", "__CRM_HANGUP=1") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/398-000004a3", "sangomacrm.agi") in new stack
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: LINKEDID: 1637706303.1976
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: SOURCE: 398
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: DESTINATION: 14243
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: DIRECTION: OUTBOUND
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: EXTTOCALL:
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: START
[2021-11-24 00:25:51] VERBOSE[8971][C-000003ff] res_agi.c: sangomacrm.agi: SCRIPT: php /var/www/html/admin/modules/sangomacrm/importOne.php 'eyJ1dWlTc2Iiwic291cmNlIjoiMzk4IiwiZGVzyYXdfdHlwZSI6IiIsInp1bHVfdHlwZSI6IiIsInp1bHVfdXJsIjoiIiwiZXh0dG9jYWxsIjoiIiwiY251bSI6IjMxNTgxMDEiLCJjbmFtIjoiIiwiY2FsbHBvcCI6ZmFsc2UsInZvaWNlbWFpbCI6IiJ9' > /dev/null 2>&1 &
[2021-11-24 00:25:52] VERBOSE[8971][C-000003ff] res_agi.c: <PJSIP/398-000004a3>AGI Script sangomacrm.agi completed, returning 0
[2021-11-24 00:25:52] VERBOSE[8971][C-000003ff] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/398-000004a3", "") in new stack
[2021-11-24 00:25:52] VERBOSE[8971][C-000003ff] app_stack.c: Spawn extension (restrictedroute-c81e728d9d4c2f636f067f89cc14862c, h, 1) exited non-zero on 'PJSIP/398-000004a3'
[2021-11-24 00:25:52] VERBOSE[8971][C-000003ff] app_stack.c: PJSIP/398-000004a3 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2021-11-24 00:25:52] VERBOSE[8972][C-000003ff] app_mixmonitor.c: MixMonitor close filestream (mixed)

david55 · November 29, 2021, 2:35pm

Please provide a log for the complete call at pastebin.freepbx.org.

ansxley · November 29, 2021, 9:18pm

Thank you for your reply, and time.

https://pastebin.freepbx.org/view/9ca759a9
The trace explanation is :

398(ext over the internet) connects to PBX, and calls a PRI line after entering the user code.
Note: the use of PRI is just an example, same behavior is observed when another extension is called.
Call terminates after 30sec’s once the call has been connected.

ansxley · December 2, 2021, 8:06am

Bump.

david55 · December 2, 2021, 10:32am

I see a normal termination, which I think is by the calling party, but I’m not completely sure about whether the default FreePBX logging level includes the sort of message that I would expect if Asterisk fails the call.

30 seconds is typically the result of a missing response, which would normally produce a log message about “not reply to critical response/request”, if Asterisk detected it.

It could be that this is the case, and the calling side is getting in first in closing the call.

It could also be lack of RTP (which would also produce one way audio), or DNS failures, but they tend not to be set with 30 second timeouts.

The normal reasons for missing responses are misconfiguration of NAT, e.g. failing to provide a public address, failing to declare local networks as loacal, etc.

Getting “pjsip set logger on” output might provide more information, or at least confirm that the caller was dropping the call.

david55 · December 2, 2021, 11:22am

30 seconds is also often used as a timeout for unanswered calls, but the cal here appears to be answered. However, it is possible that a failure to receive the answer indication is causing the caller to abandon before they abandon because of failing to receive any response at all.

ansxley · December 2, 2021, 12:23pm

The audio is perfect, and 2 way

It could also be lack of RTP (which would also produce one way audio)

which is not the case, as there is audio both the ways.

pjsip set logger on

I will set this on later when there is low traffic and collect logs, and Pcap as well.

The image is a capture i got from the interface, the red is public-ip, and black is the PABX, it shows that the PABX initiated the BYE.

ansxley · December 2, 2021, 12:29pm

This is an interesting possibility. What is unusual is that the behaviour is consistent at 30 seconds, and not a once off ( in case of packet drop or something)

david55 · December 2, 2021, 12:35pm

This clearly shows that Asterisk never received an ACK from the A party. That should have produced some sort of error message, so maybe the default logging level is too low, or maybe chan_pjsip doesn’t report this as well as chan_sip.

The usual cause for this is failing to configure NAT correctly on Asterisk, in particular failing to set the external signalling address or setting it incorrectly, resulting in the wrong value being sent in the Contact header of the OK.

The fact that you have two way audio strongly suggests that the caller received the OKs (and the 183s).

system · January 2, 2022, 12:36pm

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