Outbound Call Delay

[PCTurnkey]

As of a few weeks ago, our phone system developed a long delay when making outbound calls- usually around 15 seconds. There is zero delay when calling internal extensions. I haven't made any system changes or modifications in that time. I've reset the system and the Patton 4114 gateway we use. I don't believe this has to do with an outgoing rule that waits a certain amount of time before dialing since I always hit either 'send' or '#'.

Please help me troubleshoot this problem. I'm looking for suggestions on what settings could be responsible for this or other things to check. I'm new to 3CX (<1yr) and am still learning a lot about VoIP and this system.

 

[leejor]

The 3Cx log should show the time when the PBX receives the call from the set, and how long it takes to process it before sending out on a trunk. If there is no appreciable delay shown, then it may be a change in the settings of the extension itself, perhaps a new config file was downloaded?

The other delay could be once the call is passed on to your gateway, or VoIP provider.

 

[PCTurnkey]

From the log, it looks like the PBX logs the request from my handset immediately. After that, it looks like there is a bit of activity going on for the next 7-10 seconds. Then it looks like it completes the connection.
Unfortunately, I don't understand what's going on in the log. I do see what looks like some failures, though, on different ports.
It says [dialed number]@10.0.0.7:5060 has failed; cause: 487 request terminated. Same thing with port 5062. When it fails with port 5066 it says Cause: 502 Bad Gateway. Then it looks like it connects using 5064.

Does this make sense? Should I post the log?

 

[leejor]

It sounds as if some of the ports on your gateway are not working properly. If you post the make/model, and your settings, someone on the forum, familiar with that model cam probably chime in.

Were there any changes made to your system about the time that this problem began?

 

[3CXfoxhallsolutions]

I have sometimes seen problems with call delays being caused by DNS issues on the 3CX server. If the 3CX server is having problems resolving local and/or Internet addresses, it seems to cause delays in call set up.
I know you are using analogue lines, but check how quickly the 3CX server resolves website addresses via browser ... If it's slow to connect to websites, this could mean that you need to look at DNS issues on your LAN ...
best regards ...

 

[PCTurnkey]

Gateway is Patton Smartnode 4114 4FXO.
No changes have been made to the server or any programs on it to my knowledge. I think Windows automatic updates is turned off for this reason. I will look and see if any updates were installed.

The DNS seems to be resolving correctly and promptly.

 

[PCTurnkey]

Here is a log from a call:

10:37:38.978|.\CallCtrl.cpp(346)|Log2||CallCtrl:nIncomingCall:[CM503001]: Call(279): Incoming call from Ext.101 to <sip:[email protected]><br>
10:37:38.979|.\Extension.cpp(1407)|Log3||Extension:rintEndpointInfo:[CM505001]: Ext.101: Device info: Device Identified: [Man: Grandstream;Mod: GXP Series;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Grandstream GXP2120 1.0.4.9] PBX contact: [sip:[email protected]:5060]<br>
10:37:38.981|.\CallCtrl.cpp(529)|Log3||CallCtrl:nSelectRouteReq:[CM503010]: Making route(s) to <sip:[email protected]><br>
10:37:38.981|.\CallCtrl.cpp(708)|Log2||CallCtrl:nSelectRouteReq:[CM503004]: Call(279): Route 1: PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5062,Dev:sip:[email protected]:5066,Dev:sip:[email protected]:5064]<br>
10:37:38.982|.\CallCtrl.cpp(708)|Log2||CallCtrl:nSelectRouteReq:[CM503004]: Call(279): Route 2: PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5062,Dev:sip:[email protected]:5066,Dev:sip:[email protected]:5064]<br>
10:37:38.982|.\CallCtrl.cpp(708)|Log2||CallCtrl:nSelectRouteReq:[CM503004]: Call(279): Route 3: PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5062,Dev:sip:[email protected]:5066,Dev:sip:[email protected]:5064]<br>
10:37:39.028|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(279): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060]<br>
10:37:40.439|.\CallLeg.cpp(326)|Log2||CallLeg:nFailure:[CM503003]: Call(279): Call to sip:[email protected]:5060 has failed; Cause: 487 Request Terminated; from IP:10.0.0.7:5060<br>
10:37:40.444|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(279): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5062]<br>
10:37:41.819|.\CallLeg.cpp(326)|Log2||CallLeg:nFailure:[CM503003]: Call(279): Call to sip:[email protected]:5062 has failed; Cause: 487 Request Terminated; from IP:10.0.0.7:5062<br>
10:37:41.823|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(279): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5066]<br>
10:37:42.050|.\CallLeg.cpp(326)|Log2||CallLeg:nFailure:[CM503003]: Call(279): Call to sip:[email protected]:5066 has failed; Cause: 502 Bad Gateway; from IP:10.0.0.7:5066<br>
10:37:42.055|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(279): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5064]<br>
10:37:44.735|.\Call.cpp(42)|Log3||??:Currently active calls - 1: [279]<br>
10:37:45.627|.\CallLeg.cpp(315)|Log3||CallLeg:nAnswer:[CM503002]: Call(279): Alerting sip:[email protected]:5064<br>
10:37:45.627|.\Line.cpp(1452)|Log2||Line:rintEndpointInfo:[CM505002]: Gateway:[PATTON_SN4114] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Patton SN4114 JO EUI 00A0BA0741B1 R6.1 2012-03-07 H323 SIP FXS FXO M5T SIP Stack/4.0.30.30] PBX contact: [sip:[email protected]:5060]<br>
10:37:45.632|.\CallCtrl.cpp(885)|Log2||CallCtrl:nLegConnected:[CM503007]: Call(279): Device joined: sip:[email protected]:5060<br>
10:37:45.633|.\CallCtrl.cpp(885)|Log2||CallCtrl:nLegConnected:[CM503007]: Call(279): Device joined: sip:[email protected]:5064<br>
10:38:04.932|.\Call.cpp(1396)|Log2||Call::Terminate:[CM503008]: Call(279): Call is terminated<br>

 

[leejor]

This log just re-affirms that the gateway is unable to complete a call on port 5060, 5062 and 5066, but finally succeeds on 5064.

Call to sip:[email protected]:5060 has failed; Cause: 487 Request Terminated; from IP:10.0.0.7:5060<br>

Call to sip:[email protected]:5062 has failed; Cause: 487 Request Terminated; from IP:10.0.0.7:5062<br>

Call(279): Call to sip:[email protected]:5066 has failed; Cause: 502 Bad Gateway; from IP:10.0.0.7:5066<br>

So...either a setting in the gateway has changed, or, there is some sort of corruption in the gateway (reset needed?), or...there is an issue with the actual phone lines attached to those ports.

You may want to confirm that the phone lines are actually working by unplugging each phone line in question and plugging it into a phone. Are you receiving incoming calls on these lines?
.
A power down/up may reset the gateway, if that is, in fact, what is causing the problem.

 

[PCTurnkey]

I'm wondering if something happened to the gateway. I'm remembering we did have a power outage a month or so ago, possibly around the time this started. I thought I saved my config, but maybe something got corrupted. Wondering now if I need to reload some defaults and reboot.

 

[leejor]

I'm remembering we did have a power outage a month or so ago, possibly around the time this started. I thought I saved my config, but maybe something got corrupted. Wondering now if I need to reload some defaults and reboot.

If the issue hasn't gone away on it's own, that might be something worth considering...along with a UPS.

 

[PCTurnkey]

Issue hasn't resolved yet. I did a factory reset on the Patton gateway and reconfigured it with the 3cx generated config file. It seems like it's trimmed a few seconds off the connection time, but still takes about 6 seconds or more from the time time I hit send to the time it connects and starts ringing.

The log file looks the same still:

09:05:48.662|.\CallCtrl.cpp(346)|Log2||CallCtrl:nIncomingCall:[CM503001]: Call(308): Incoming call from Ext.101 to <sip:[email protected]><br>
09:05:48.664|.\Extension.cpp(1407)|Log3||Extension:rintEndpointInfo:[CM505001]: Ext.101: Device info: Device Identified: [Man: Grandstream;Mod: GXP Series;Rev: General] Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Grandstream GXP2120 1.0.4.9] PBX contact: [sip:[email protected]:5060]<br>
09:05:48.667|.\CallCtrl.cpp(529)|Log3||CallCtrl:nSelectRouteReq:[CM503010]: Making route(s) to <sip:[email protected]><br>
09:05:48.668|.\CallCtrl.cpp(708)|Log2||CallCtrl:nSelectRouteReq:[CM503004]: Call(308): Route 1: PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5062,Dev:sip:[email protected]:5066,Dev:sip:[email protected]:5064]<br>
09:05:48.669|.\CallCtrl.cpp(708)|Log2||CallCtrl:nSelectRouteReq:[CM503004]: Call(308): Route 2: PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5062,Dev:sip:[email protected]:5066,Dev:sip:[email protected]:5064]<br>
09:05:48.669|.\CallCtrl.cpp(708)|Log2||CallCtrl:nSelectRouteReq:[CM503004]: Call(308): Route 3: PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5062,Dev:sip:[email protected]:5066,Dev:sip:[email protected]:5064]<br>
09:05:48.705|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(308): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5060]<br>
09:05:50.181|.\CallLeg.cpp(326)|Log2||CallLeg:nFailure:[CM503003]: Call(308): Call to sip:[email protected]:5060 has failed; Cause: 487 Request Terminated; from IP:10.0.0.7:5060<br>
09:05:50.186|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(308): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5062]<br>
09:05:51.641|.\CallLeg.cpp(326)|Log2||CallLeg:nFailure:[CM503003]: Call(308): Call to sip:[email protected]:5062 has failed; Cause: 487 Request Terminated; from IP:10.0.0.7:5062<br>
09:05:51.646|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(308): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5066]<br>
09:05:51.870|.\CallLeg.cpp(326)|Log2||CallLeg:nFailure:[CM503003]: Call(308): Call to sip:[email protected]:5066 has failed; Cause: 502 Bad Gateway; from IP:10.0.0.7:5066<br>
09:05:51.876|.\Target.cpp(441)|Log2||Target::makeOneInvite:[CM503025]: Call(308): Calling PSTNline:6011982@(Ln.10001@PATTON_SN4114)@[Dev:sip:[email protected]:5064]<br>
09:05:55.441|.\CallLeg.cpp(315)|Log3||CallLeg:nAnswer:[CM503002]: Call(308): Alerting sip:[email protected]:5064<br>
09:05:55.441|.\Line.cpp(1452)|Log2||Line:rintEndpointInfo:[CM505002]: Gateway:[PATTON_SN4114] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [Patton SN4114 JO EUI 00A0BA0741B1 R6.2 2012-09-11 H323 SIP FXS FXO M5T SIP Stack/4.0.30.30] PBX contact: [sip:[email protected]:5060]<br>
09:05:55.447|.\CallCtrl.cpp(885)|Log2||CallCtrl:nLegConnected:[CM503007]: Call(308): Device joined: sip:[email protected]:5060<br>
09:05:55.448|.\CallCtrl.cpp(885)|Log2||CallCtrl:nLegConnected:[CM503007]: Call(308): Device joined: sip:[email protected]:5064<br>
09:06:01.607|.\Call.cpp(1396)|Log2||Call::Terminate:[CM503008]: Call(308): Call is terminated<br>

I'm also curious about what's going on in the log before the call was attempted. There are quite a few entries that look like errors with STUN:

08:58:45.466|.\StunClient.cpp(356)|Log2|STUN|StunClient:nInitTests:[CM506001]: STUN request to resolve SIP external IPort mapping is sent to STUN server [ V4 199.192.206.228:3478 UDP target domain=unspecified mFlowKey=0 ] over Transport [ V4 10.0.0.82:5060 UDP target domain=unspecified mFlowKey=0 ]<br>
08:58:45.508|.\StunClient.cpp(141)|Log2|STUN|StunClient:rocess:[CM506003]: Resolved SIP external IPort has changed to ([ V4 24.248.209.34:26158 UDP target domain=unspecified mFlowKey=0 ]) on Transport [ V4 10.0.0.82:5060 UDP target domain=unspecified mFlowKey=0 ]<br>
08:58:45.660|.\StunClient.cpp(109)|Error1|STUN|StunClient:rocess:[CM306003]: SIP IPort mapping ([ V4 24.248.209.34:26158 UDP target domain=unspecified mFlowKey=0 ]) resolved by STUN server [ V4 199.192.206.228:3478 UDP target domain=unspecified mFlowKey=0 ] differs from the one ([ V4 24.248.209.34:51934 UDP target domain=unspecified mFlowKey=0 ] resolved by STUN server 178.238.134.190<br>
08:58:45.730|.\StunClient.cpp(109)|Error1|STUN|StunClient:rocess:[CM306003]: SIP IPort mapping ([ V4 24.248.209.34:26158 UDP target domain=unspecified mFlowKey=0 ]) resolved by STUN server [ V4 199.192.206.228:3478 UDP target domain=unspecified mFlowKey=0 ] differs from the one ([ V4 24.248.209.34:41291 UDP target domain=unspecified mFlowKey=0 ] resolved by STUN server 173.212.195.222<br>
08:58:45.730|.\StunClient.cpp(109)|Error1|STUN|StunClient:rocess:[CM306003]: SIP IPort mapping ([ V4 24.248.209.34:51934 UDP target domain=unspecified mFlowKey=0 ]) resolved by STUN server [ V4 178.238.134.190:3478 UDP target domain=unspecified mFlowKey=0 ] differs from the one ([ V4 24.248.209.34:41291 UDP target domain=unspecified mFlowKey=0 ] resolved by STUN server 173.212.195.222<br>

Don't know if they are related or if that is normal, but thought I'd put that out there.

I realized that we didn't have a UPS on this part of the system and just got a few ready and set to install. Thanks for the advice.

Any suggestions on where to go from here?

 

[leejor]

Did you confirm that all of the phone lines are working (at the end of the cord plugged into the gateway) ? In the past, one reason for Cause: 502 Bad Gateway has been the result of a non working phone line.

Not sure about the reason for the STUN logs. STUN is simply a tool to determine the type of NAT that a system is located behind. I like the diagram at this site, makes an explanation quire simple... http://en.wikipedia.org/wiki/STUN

Given that your gateway in an internal device, it should not be affected. If you also had trunks to a VoIP provider, then, you could, possibly, have an issue.