8-10 second delay in call processing

Hi there,

I have a strange delay in call processing. It takes a long time to place calls, no matter if internally or outbound. Log files state that it takes 9 (nine) seconds from dialing to ringing.
This has happened twice before, but that behavior stopped after a couple of hours. But this time it’s rather persistent. This time the delay started after I updated FreePBX Core a couple of days ago. The next update, a few days after the initial update, didn’t change anything. Rebooting did not help either.
I’m hoping someone out there can help me, getting really frustrated…

FreePBX 12.0.76.4 with Asterisk Ver. 11.17.1
PBX Firmware:6.12.65-27 PBX Service Pack:1.0.0.0

Following is an excerpt from the log file, showing the 9 second delay doing an internal sip to sip call.

[2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:1] Goto("SIP/66-00000ab8", "state-,1") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Goto (sub-presencestate-display,state-,1) [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:1] Set("SIP/66-00000ab8", "PRESENCESTATE_DISPLAY=") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:2] Return("SIP/66-00000ab8", "") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:40] Set("SIP/66-00000ab8", "CONNECTEDLINE(name,i)=XXX") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:41] Set("SIP/66-00000ab8", "CONNECTEDLINE(num)=34") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:42] Set("SIP/66-00000ab8", "D_OPTIONS=TtrI") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:43] Macro("SIP/66-00000ab8", "dialout-one-predial-hook,") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:1] MacroExit("SIP/66-00000ab8", "") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:44] ExecIf("SIP/66-00000ab8", "0?Set(D_OPTIONS=trII)") in new stack [2016-08-10 10:48:35] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:45] Dial("SIP/66-00000ab8", "SIP/34,,TtrI") in new stack [2016-08-10 10:48:44] VERBOSE[542][C-000035dc] netsock2.c: == Using SIP RTP TOS bits 184 [2016-08-10 10:48:44] VERBOSE[542][C-000035dc] netsock2.c: == Using SIP RTP CoS mark 5 [2016-08-10 10:48:44] VERBOSE[542][C-000035dc] app_dial.c: -- Called SIP/34 [2016-08-10 10:48:44] VERBOSE[542][C-000035dc] app_dial.c: -- Connected line update to SIP/66-00000ab8 prevented. [2016-08-10 10:48:44] VERBOSE[542][C-000035dc] app_dial.c: -- SIP/34-00000ab9 is ringing [2016-08-10 10:48:46] VERBOSE[542][C-000035dc] app_dial.c: -- Connected line update to SIP/66-00000ab8 prevented. [2016-08-10 10:48:46] VERBOSE[542][C-000035dc] app_dial.c: -- SIP/34-00000ab9 answered SIP/66-00000ab8 [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:1] Macro("SIP/66-00000ab8", "hangupcall,") in new stack [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/66-00000ab8", "0?Set(CDR(recordingfile)=.wav)") in new stack [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/66-00000ab8", "1?theend") in new stack [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: -- Goto (macro-hangupcall,s,4) [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: -- Executing [[email protected]:4] Hangup("SIP/66-00000ab8", "") in new stack [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/66-00000ab8' in macro 'hangupcall' [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: == Spawn extension (macro-dial-one, h, 1) exited non-zero on 'SIP/66-00000ab8' [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] app_macro.c: == Spawn extension (macro-dial-one, s, 45) exited non-zero on 'SIP/66-00000ab8' in macro 'dial-one' [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on 'SIP/66-00000ab8' in macro 'exten-vm' [2016-08-10 10:49:30] VERBOSE[542][C-000035dc] pbx.c: == Spawn extension (ext-local, 34, 2) exited non-zero on 'SIP/66-00000ab8'

Asterisk is running a few versions behind, an update may fix this. Otherwise, I have no idea, the log lines don’t indicate anything that makes me think this is caused by Core.

Thx for your reply. What is the easiest way to update asterisk? Are there any implications in updating asterisk, i.e. loss of config etc.?

If you are running the distro:
http://wiki.freepbx.org/pages/viewpage.action?pageId=1409034

A long delay like this is sometimes caused by DNS interaction. I don’t know what (if anything) might be jamming you up. If you are using DynDNS for anything, or if you are using hostnames in your configs (like maybe your SIP provider), you might be able to speed things up by coding entries in your hosts file.

Under Settings —> Asterisk SIP Settings, do you have a STUN server defined? I had this problem once, removed the STUN server definition (made it blank), and everything started working fine.

I’m sure this was some sort of networking issue outside of my FreePBX server that caused it, but it solved my problem.

2 Likes

A long delay (5, or 10 seconds, exactly) is always a DNS issue. The Default DNS timeout is 5 seconds, so if you have a delay of 5 seconds (or 10 seconds), that is the reason.

Usually the /etc/resolv.conf is pointing to a machine that is not responding.

WOW! I’ve been googling this for weeks and weeks! All I ever found was dialplan dialplan and dialplan. This fixed my issue!

how your issue is resolved.

I’m having the same problem. It might just be a DNS issue; I’m trying to figure out where. What did you do to resolve your problem?

OH - this is an ancient thread… whoops…