Dismiss Notice
We would like to remind you that we’re updating our login process for all 3CX forums whereby you will be able to login with the same credentials you use for the Partner or Customer Portal. Click here to read more.

Lag for outgoing calls about half the time...

Discussion in '3CX Phone System - General' started by rshores, Apr 18, 2016.

Thread Status:
Not open for further replies.
  1. rshores

    Joined:
    Oct 22, 2014
    Messages:
    25
    Likes Received:
    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:######_CLIENTNAME@SERVERLOCATION.SIP_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:######_CLIENTNAME@SERVERLOCATION.SIP_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:######_CLIENTNAME@SERVERLOCATION.SIP_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!
     
  2. craigreilly

    craigreilly Well-Known Member

    Joined:
    Feb 1, 2012
    Messages:
    3,575
    Likes Received:
    305
    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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  3. NickD_3CX

    NickD_3CX Support Team
    Staff Member 3CX Support

    Joined:
    Jun 2, 2014
    Messages:
    1,380
    Likes Received:
    84
    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.
     
  4. rshores

    Joined:
    Oct 22, 2014
    Messages:
    25
    Likes Received:
    0
    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.
     
  5. rshores

    Joined:
    Oct 22, 2014
    Messages:
    25
    Likes Received:
    0
    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.
     
  6. craigreilly

    craigreilly Well-Known Member

    Joined:
    Feb 1, 2012
    Messages:
    3,575
    Likes Received:
    305
    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;
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  7. rshores

    Joined:
    Oct 22, 2014
    Messages:
    25
    Likes Received:
    0
    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.
     
  8. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,126
    Likes Received:
    330
    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.
     
  9. rshores

    Joined:
    Oct 22, 2014
    Messages:
    25
    Likes Received:
    0
    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.

     
  10. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,126
    Likes Received:
    330
    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?
     
  11. rshores

    Joined:
    Oct 22, 2014
    Messages:
    25
    Likes Received:
    0
    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:SIP_USERNAME@atlanta.voip.ms: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:SIP_USERNAME@atlanta.voip.ms: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:SIP_USERNAME@atlanta.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>>1DIALED_NUMBER@[Dev:sip:SIP_USERNAME@atlanta.voip.ms: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:115@192.168.0.126:5060> for device Dev(56):[sip:115@192.168.0.126: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:115@192.168.0.126:5060 / 115]
    19-Apr-2016 07:49:26.776	Endpoint Extn:115 has removed contact <sip:115@192.168.0.126: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]
     
  12. NickD_3CX

    NickD_3CX Support Team
    Staff Member 3CX Support

    Joined:
    Jun 2, 2014
    Messages:
    1,380
    Likes Received:
    84
    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.
     
  13. positron

    Joined:
    Jan 14, 2013
    Messages:
    76
    Likes Received:
    11
    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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
Thread Status:
Not open for further replies.