• V20: 3CX Re-engineered. Get V20 for increased security, better call management, a new admin console and Windows softphone. Learn More.

Lag for outgoing calls about half the time...

Status
Not open for further replies.

rshores

Joined
Oct 22, 2014
Messages
25
Reaction score
0
Our clients are experiencing frequent lag when placing calls. Sometime, they'll pick up the phone and dial, and it will immediately connect, and sometimes there will be a 10-15 second delay. When the call is delayed, a message such as the following is entered into the activity log:

Code:
18-Apr-2016 15:27:53.290	[CM505003]: Provider:[PROVIDER_NAME] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [voip.ms] PBX contact: [sip:######_CLIENTNAME@CORRECT IP ADDRESS:5060]

Redacted information:
  • Provider name
    SIP # in User ID
    Client name is User ID
    Client IP address

When calls go through just fine, the following log entries are made:

Code:
18-Apr-2016 14:29:04.222	[CM503025]: Call(C:4065): Calling T:Line:10001>>NUMBER_CALLED@[Dev:sip:######[email protected]_TRUNK_PROVIDER:5060] for L:4065.1[Extn]
18-Apr-2016 14:29:04.190	[CM503027]: Call(C:4065): From: Extn:115 ("115" <sip:###@3CX.SERVERIPADDRESS:5060>)  to  T:Line:10001>>NUMBER_CALLED@[Dev:sip:######[email protected]_TRUNK_PROVIDER:5060]
18-Apr-2016 14:29:04.190	[CM503004]: Call(C:4065): Route 1: from L:4065.1[Extn] to T:Line:10001>>NUMBER_CALLED@[Dev:sip:######[email protected]_TRUNK_PROVIDER:5060]
18-Apr-2016 14:29:04.190	Call(C:4065): Call from Extn:115 to LOCAL_TEL_NUMBER matches outbound rule 'SIP_PROVIDER_NAME Local'

Same general information sanitized from this log as well.

Does anyone have any ideas on where we could be going wrong?

Thanks!
 
May be a dumb question - is the user using the SEND command or # when finished dialing in either scenario?

This is always a concern when using an unsupported SIP Provider. However, Voip.ms tech support is pretty good and a few are familiar with the 3cx setup. I would try their tech support.
 
If the system is not a V14, I would recommend checking under Settings -> Network -> STUN Server, and make sure you have a Static IP selected there and not using the STUN Servers. This has been known to cause delays in the past as the system tries to resolve its Public IP address first before making the call.
 
Not a dumb question at all.... I may be the dumb one here, because I'm not sure where to check that. I'm assuming that this will be shown/set in a dialing string setting somewhere, but I haven't been able to figure out where.

One change that I have made though.... we don't use STUN, and on the provider settings -> advanced page, "Which IP to use in 'Contact' field for registration:", "External (STUN)" was selected. I changed that to "specified IP", and entered their external IP address. Additionally, "Require registration for:" was set for "Incoming and Outgoing". Per a conversation with VOIP.ms tech support this morning, outgoing calls do not require authorization, so I changed that as well.

Had a user test it, and still saw the same entry in the Server Activity Log:

Code:
 [CM505003]: Provider:[VoIP.ms] Device info: Device Not Identified: User Agent not matched;

But the user I've been having test this reported that her call started ringing instantly. With this being an intermittent issue, I'm hesitant to stick a fork in it though.
 
NickD_3CX said:
If the system is not a V14, I would recommend checking under Settings -> Network -> STUN Server, and make sure you have a Static IP selected there and not using the STUN Servers. This has been known to cause delays in the past as the system tries to resolve its Public IP address first before making the call.

STUN was turned off there, but on trunk -> advanced, "IP to use in 'Contact' field for registration:" it was set to "External (STUN resolved)". I've changed that to "Specified IP" and populated it with their public address.
 
If it is working - I would not be concerned with the string
Code:
[CM505003]: Provider:[VoIP.ms] Device info: Device Not Identified: User Agent not matched;
 
Yeah, I thought there was a correlation between the presence of that message and the delay in outgoing calls, but it doesn't appear to be the case. Still monitoring, but based on user feedback, I'm cautiously optimistic.
 
Since each log entry is time stamped, you should be able to see between what two entries the delay is occurring. You didn't post enough continuous logs, of one call, to make that clear.
 
leejor said:
Since each log entry is time stamped, you should be able to see between what two entries the delay is occurring. You didn't post enough continuous logs, of one call, to make that clear.

Good point. Here's a log, start to finish for a single call (from a softphone on our network - this mirrors the results we saw from a handset on their network though)... this is on another trunk that we're running into their system for testing. There was a delay on this call, as you can see from the log between 16:46:49 and 16:46:57. I can make the same changes to the STUN settings for that trunk, but with this not being a consistent problem, I still can't really close it out. I'll monitor it until tomorrow afternoon, unless someone sees something in the log below that's screaming at them.

19-Apr-2016 16:47:00.207 Leg L:138.2[Line:10000>>DIALED_NUMBER] is terminated: Cause: BYE from PBX
19-Apr-2016 16:47:00.207 [CM503008]: Call(C:138): Call is terminated
19-Apr-2016 16:47:00.206 Leg L:138.1[Extn] is terminated: Cause: BYE from OUR_IP_ADDRESS:6188
19-Apr-2016 16:46:59.645 PBX has dropped a message with 'User-Agent: friendly-scanner' from IP 63.141.241.90 because it is on blocked UAs list
19-Apr-2016 16:46:57.878 [CM503007]: Call(C:138): Line:10000>>DIALED_NUMBER has joined, contact <sip:SIP_USERNAME@SERVER_LOCATION.voip.ms:5060>
19-Apr-2016 16:46:57.878 [CM503007]: Call(C:138): Extn:115 has joined, contact <sip:115@OUR_IP_ADDRESS:6188>
19-Apr-2016 16:46:57.877 L:138.2[Line:10000>>DIALED_NUMBER] has joined to L:138.1[Extn]
19-Apr-2016 16:46:57.155 [CM505003]: Provider:[VoIP.ms 2] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:SIP_USERNAME@THEIR_IP_ADDRESS:5060]
19-Apr-2016 16:46:49.887 [CM503025]: Call(C:138): Calling T:Line:10000>>DIALED_NUMBER@[Dev:sip:SIP_USERNAME@SERVER_LOCATION.voip.ms:5060] for L:138.1[Extn]
19-Apr-2016 16:46:49.838 [CM503027]: Call(C:138): From: Extn:115 ("115" <sip:115@THEIR_IP_ADDRESS:5060>) to T:Line:10000>>DIALED_NUMBER@[Dev:sip:SIP_USERNAME@SERVER_LOCATION.voip.ms:5060]
19-Apr-2016 16:46:49.838 [CM503004]: Call(C:138): Route 1: from L:138.1[Extn] to T:Line:10000>>DIALED_NUMBER@[Dev:sip:SIP_USERNAME@SERVER_LOCATION.voip.ms:5060]
19-Apr-2016 16:46:49.838 Line limit check: Current # of calls for line Lc:10000(@VoIP.ms 2[<sip:SIP_USERNAME@SERVER_LOCATION.voip.ms:5060>]) is 0; limit is 25
19-Apr-2016 16:46:49.838 Call(C:138): Call from Extn:115 to DIALED_NUMBER matches outbound rule 'Rule for VoIP.ms 2'
19-Apr-2016 16:46:49.837 [CM503001]: Call(C:138): Incoming call from Extn:115 to <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
 
Have you had a look at a call log in Verbose mode to see if there as any additional information show during that 7 second period? I'm wondering (and perhaps the use of Wireshark might be the way to confirm this) if the seven seconds is the time it takes for the provider to send a SIP acknowledged that the digits are being processed, or was the call only (finally) set-up to the destination after 7 seconds? Have you any other VoIP providers that you get the same behaviour with? Have you brought this up with your provider and requested any information that they might be able to provide? Do they see any delay after receiving the Invite from you?
 
Here's the verbose log for that specific call... nothing is jumping out at me, but maybe someone will see something... to be honest, it might be purely academic at this point - since I made the changes to the authentication settings for the trunk, they haven't encountered the problem again. As I said before, I'm cautiously optimistic... but with it being an intermittent issue to start out with, I don't know if I'll ever be able to verify that it's been completely addressed, or if one or two people still have the issue occasionally but don't bother to say anything.

Code:
19-Apr-2016 16:46:57.878	Session 27184 of leg L:138.1[Extn] is connected
19-Apr-2016 16:46:57.878	L:138.1[Extn] got Connected.UAS Send 200/INVITE from 0.0.0.0:0 tid=Pjd2e7cd42118f46fda1cef48f497b1dc8 Call-ID=2cf02538c96942d2bda1e09603c7813e:
			SIP/2.0 200 OK
			Via: SIP/2.0/UDP OUR_IP_ADDRESS:6188;rport=6188;branch=z9hG4bKPjd2e7cd42118f46fda1cef48f497b1dc8
			Contact: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
			To: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>;tag=b60f6351
			From: "115"<sip:115@THEIR_IP_ADDRESS:5060>;tag=caae641d94e74fe1bb51ae79c92a8cc4
			Call-ID: 2cf02538c96942d2bda1e09603c7813e
			CSeq: 5468 INVITE
			Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
			Content-Type: application/sdp
			Supported: replaces
			User-Agent: 3CXPhoneSystem 12.0.41311.996 (34969)
			Content-Length: 312
			
			v=0
			o=3cxPS 114051514368 479106957313 IN IP4 THEIR_IP_ADDRESS
			s=3cxPS Audio call
			c=IN IP4 THEIR_IP_ADDRESS
			t=0 0
			m=audio 9032 RTP/AVP 0 8 3 96
			a=rtpmap:0 PCMU/8000
			a=rtpmap:8 PCMA/8000
			a=rtpmap:3 GSM/8000
			a=rtpmap:96 telephone-event/8000
			a=fmtp:96 0-15
			a=sendrecv
			m=video 0 RTP/AVP 31
			c=IN IP4 127.0.0.1
19-Apr-2016 16:46:57.878	L:138.1[Extn] Sending: OnSendResp Send 200/INVITE from 0.0.0.0:0 tid=Pjd2e7cd42118f46fda1cef48f497b1dc8 Call-ID=2cf02538c96942d2bda1e09603c7813e:
			SIP/2.0 200 OK
			Via: SIP/2.0/UDP OUR_IP_ADDRESS:6188;rport=6188;branch=z9hG4bKPjd2e7cd42118f46fda1cef48f497b1dc8
			Contact: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
			To: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>;tag=b60f6351
			From: "115"<sip:115@THEIR_IP_ADDRESS:5060>;tag=caae641d94e74fe1bb51ae79c92a8cc4
			Call-ID: 2cf02538c96942d2bda1e09603c7813e
			CSeq: 5468 INVITE
			Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
			Content-Type: application/sdp
			Supported: replaces
			Content-Length: 312
			
			v=0
			o=3cxPS 114051514368 479106957313 IN IP4 THEIR_IP_ADDRESS
			s=3cxPS Audio call
			c=IN IP4 THEIR_IP_ADDRESS
			t=0 0
			m=audio 9032 RTP/AVP 0 8 3 96
			a=rtpmap:0 PCMU/8000
			a=rtpmap:8 PCMA/8000
			a=rtpmap:3 GSM/8000
			a=rtpmap:96 telephone-event/8000
			a=fmtp:96 0-15
			a=sendrecv
			m=video 0 RTP/AVP 31
			c=IN IP4 127.0.0.1
19-Apr-2016 16:46:57.877	L:138.1[Extn]: Terminating targets, reason: SIP ;cause=200 ;text="Call completed elsewhere"
19-Apr-2016 16:46:57.877	L:138.2[Line:10000>>1DIALED_NUMBER] has joined to L:138.1[Extn]
19-Apr-2016 16:46:57.156	L:138.1[Extn] Sending: OnSendResp Send 183/INVITE from 0.0.0.0:0 tid=Pjd2e7cd42118f46fda1cef48f497b1dc8 Call-ID=2cf02538c96942d2bda1e09603c7813e:
			SIP/2.0 183 Session Progress
			Via: SIP/2.0/UDP OUR_IP_ADDRESS:6188;rport=6188;branch=z9hG4bKPjd2e7cd42118f46fda1cef48f497b1dc8
			Contact: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
			To: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>;tag=b60f6351
			From: "115"<sip:115@THEIR_IP_ADDRESS:5060>;tag=caae641d94e74fe1bb51ae79c92a8cc4
			Call-ID: 2cf02538c96942d2bda1e09603c7813e
			CSeq: 5468 INVITE
			Content-Type: application/sdp
			Content-Length: 312
			
			v=0
			o=3cxPS 114051514368 479106957313 IN IP4 THEIR_IP_ADDRESS
			s=3cxPS Audio call
			c=IN IP4 THEIR_IP_ADDRESS
			t=0 0
			m=audio 9032 RTP/AVP 0 8 3 96
			a=rtpmap:0 PCMU/8000
			a=rtpmap:8 PCMA/8000
			a=rtpmap:3 GSM/8000
			a=rtpmap:96 telephone-event/8000
			a=fmtp:96 0-15
			a=sendrecv
			m=video 0 RTP/AVP 31
			c=IN IP4 127.0.0.1
19-Apr-2016 16:46:49.887	[CM503025]: Call(C:138): Calling T:Line:10000>>1DIALED_NUMBER@[Dev:sip:[email protected]:5060] for L:138.1[Extn]
19-Apr-2016 16:46:49.838	[Flow] Call(C:138): making call from L:138.1[Extn] to T:Line:10000>>1DIALED_NUMBER@[Dev:sip:[email protected]:5060]
19-Apr-2016 16:46:49.838	[CM503027]: Call(C:138): From: Extn:115 ("115" <sip:115@THEIR_IP_ADDRESS:5060>)  to  T:Line:10000>>1DIALED_NUMBER@[Dev:sip:[email protected]:5060]
19-Apr-2016 16:46:49.838	[CM503004]: Call(C:138): Route 1: from L:138.1[Extn] to T:Line:10000>>1DIALED_NUMBER@[Dev:sip:[email protected]:5060]
19-Apr-2016 16:46:49.838	Call(C:138): Call from Extn:115 to DIALED_NUMBER matches outbound rule 'Rule for VoIP.ms 2'
19-Apr-2016 16:46:49.838	[Flow] Call(C:138): has built target endpoint: Out#:>>Rule{Rule for VoIP.ms 2}>>DIALED_NUMBER for call from L:138.1[Extn]
19-Apr-2016 16:46:49.837	[CM503010]: Call(C:138): Making route(s) from Extn:115 to <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
19-Apr-2016 16:46:49.837	Remote SDP is set for leg L:138.1[Extn]
19-Apr-2016 16:46:49.837	[CM505001]: Endpoint Extn:115: Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXPhone for Windows 12.0.37098.0] PBX contact: [sip:115@THEIR_IP_ADDRESS:5060]
19-Apr-2016 16:46:49.837	[CM500002]: Call(C:138): Info on incoming INVITE from Extn:115:
			Invite-IN Recv Req INVITE from OUR_IP_ADDRESS:6188 tid=Pjd2e7cd42118f46fda1cef48f497b1dc8 Call-ID=2cf02538c96942d2bda1e09603c7813e:
			INVITE sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060 SIP/2.0
			Via: SIP/2.0/UDP OUR_IP_ADDRESS:6188;rport=6188;branch=z9hG4bKPjd2e7cd42118f46fda1cef48f497b1dc8
			Max-Forwards: 70
			Contact: "115"<sip:115@OUR_IP_ADDRESS:6188;ob>
			To: <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
			From: "115"<sip:115@THEIR_IP_ADDRESS:5060>;tag=caae641d94e74fe1bb51ae79c92a8cc4
			Call-ID: 2cf02538c96942d2bda1e09603c7813e
			CSeq: 5468 INVITE
			Session-Expires: 1800
			Min-SE: 90
			Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
			Content-Type: application/sdp
			Proxy-Authorization: Digest username="115",realm="3CXPhoneSystem",nonce="414d535c0d272a3967:026d7d0148ea6f0579eac7f760116a62",uri="sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060",response="6b9f4fd3e908d3ebe6346b37efd1d3f5",algorithm=MD5
			Supported: replaces, 100rel, timer, norefersub
			User-Agent: 3CXPhone for Windows 12.0.37098.0
			Content-Length: 353
			
			v=0
			o=- 3670073148 3670073148 IN IP4 OUR_IP_ADDRESS
			s=pjmedia
			b=AS:84
			t=0 0
			a=X-nat:0
			m=audio 42020 RTP/AVP 0 8 3 96
			c=IN IP4 OUR_IP_ADDRESS
			b=TIAS:64000
			b=AS:84
			a=rtcp:42021
			a=sendrecv
			a=rtpmap:0 PCMU/8000
			a=rtpmap:8 PCMA/8000
			a=rtpmap:3 GSM/8000
			a=rtpmap:96 telephone-event/8000
			a=fmtp:96 0-15
			m=video 0 RTP/AVP 31
			c=IN IP4 127.0.0.1
19-Apr-2016 16:46:49.837	[CM503001]: Call(C:138): Incoming call from Extn:115 to <sip:DIALED_NUMBER@THEIR_IP_ADDRESS:5060>
19-Apr-2016 07:49:29.023	Endpoint Extn:115 has added contact <sip:[email protected]:5060> for device Dev(56):[sip:[email protected]:5060 / 115]
19-Apr-2016 07:49:29.023	[CM504001]: Endpoint Extn:115: new contact is registered. Contact(s): [sip:115@OUR_IP_ADDRESS:6188 / 115,sip:[email protected]:5060 / 115]
19-Apr-2016 07:49:26.776	Endpoint Extn:115 has removed contact <sip:[email protected]:5060>
19-Apr-2016 07:49:26.776	[CM504002]: Endpoint Extn:115: a contact is unregistered. Contact(s): [sip:115@OUR_IP_ADDRESS:6188 / 115]
 
It seems as if the the 3CX Server receives the 183 Early Media 7 seconds after the INVITE it sends. Unfortunately the Activity Logs do not show the "100 Trying " message, so as leejor pointed out, maybe capturing a call on Wireshark would enlighten you more.
 
I don't know if this is related, but I had a similar issue at a client where their 3CX Windows softphone always had a delay of up to 20 seconds between clicking "Call" and before dialing actually occurred. A packet trace showed that the 3CX Windows client tried to ping the 3CX server and wasn't getting a response (because the client and server were on different internal subnets and ping wasn't allowed beyond the local subnet). It finally dialed after it gave up waiting. Once I allowed a successful ping response to the client, the delay vanished.
 
Status
Not open for further replies.
Get 3CX - Absolutely Free!

Link up your team and customers Phone System Live Chat Video Conferencing

Hosted or Self-managed. Up to 10 users free forever. No credit card. Try risk free.

3CX
A 3CX Account with that email already exists. You will be redirected to the Customer Portal to sign in or reset your password if you've forgotten it.