Connection Delay

Discussion in '3CX Phone System - General' started by red4, Apr 25, 2011.

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

    Joined:
    Feb 19, 2010
    Messages:
    8
    Likes Received:
    0
    Hi,
    I am getting a delay of between 8 and 10 seconds when receiving an incoming call, the caller hears nothing (Blank) until my phone rings, this can cause some people to hangup before my phone even rings.

    Below is the server log for an incoming test call, I terminated the call 1 second after it started to ring.

    192.168.###.24 = 3CX PBX Server
    192.168.###.105 = Cisco SPA502G Phone

    [LOG]
    13:18:56.746 [CM503008]: Call(73): Call is terminated
    13:18:53.324 [CM505001]: Ext.246: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA502G-7.4.8a] PBX contact: [sip:246@192.168.###.24:5060]
    13:18:53.324 [CM503002]: Call(73): Alerting sip:246@192.168.###.105:5060
    13:18:53.215 [CM503025]: Call(73): Calling Ext:Ext.246@[Dev:sip:246@192.168.###.105:5060]
    13:18:53.183 [CM503004]: Call(73): Route 1: Ext:Ext.246@[Dev:sip:246@192.168.###.105:5060]
    13:18:53.168 [CM503010]: Making route(s) to <sip:246@192.168.###.24:5060>
    13:18:53.168 [CM505003]: Provider:[BT VoIP] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXPhoneSystem 9.0.15776.0] PBX contact: [sip:441##63##1#6@217.43.###.86:5060]
    13:18:53.152 [CM503001]: Call(73): Incoming call from +4479##89##58@(Ln.10000@BT VoIP) to <sip:246@192.168.###.24:5060>
    13:18:46.230 [CM503012]: Inbound office hours rule (unnamed) for 10000 forwards to DN:246
    [/LOG]
     
  2. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,582
    Likes Received:
    249
    The only delay I see is between the first line at 13:18:46 and the line above at 13:18:53. Everything above happens within a second, according to the logs. At the 13:18:53.152 mark 3CX has received the caller ID and routes the call. Are you talking about a silence happening before that point ?

    Is this happening with both mobile numbers, as in your post, and landline numbers?
     
  3. red4

    Joined:
    Feb 19, 2010
    Messages:
    8
    Likes Received:
    0
    Yes, this is the delay I am talking about. Because it is so long people will be hanging up.

    There is no lag during the calls, just on the connection.


    Below is the start of both a mobile and land line call.

    Land Line
    19:05:28.742 [CM503001]: Call(10): Incoming call from +4415##86##60@(Ln.10000@BT VoIP) to <sip:246@192.168.###.24:5060>
    19:05:21.836 [CM503012]: Inbound out-of-office hours rule (unnamed) for 10000 forwards to DN:246

    Mobile
    19:02:07.929 [CM503001]: Call(9): Incoming call from +4479##89##58@(Ln.10000@BT VoIP) to <sip:246@192.168.###.24:5060>
    19:01:56.992 [CM503012]: Inbound out-of-office hours rule (unnamed) for 10000 forwards to DN:246


    FULL LOG - DETAILED
    19:20:05.000 [CM503008]: Call(1): Call is terminated
    19:20:01.765 [CM505001]: Ext.246: Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [] PBX contact: [sip:246@192.168.###.24:5060]
    19:20:01.765 [CM503002]: Call(1): Alerting sip:246@192.168.###.105:5060
    19:20:01.578 [CM503025]: Call(1): Calling Ext:Ext.246@[Dev:sip:246@192.168.###.105:5060]
    19:20:01.578 [MS210002] C:1.2:Offer provided. Connection(transcoding mode): 192.168.20.###:7000(7001)
    19:20:01.500 [CM503004]: Call(1): Route 1: Ext:Ext.246@[Dev:sip:246@192.168.###.105:5060]
    19:20:01.469 [CM503010]: Making route(s) to <sip:246@192.168.###.24:5060>
    19:20:01.469 [MS210000] C:1.1:Offer received. RTP connection: 62.239.###.204:59760(59761)
    19:20:01.469 Remote SDP is set for legC:1.1
    19:20:01.469 [CM505003]: Provider:[BT VoIP] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXPhoneSystem 9.0.15776.0] PBX contact: [sip:4415##32###6@217.43.###.86:5060]
    19:20:01.422 [CM503001]: Call(1): Incoming call from +4479##89##58@(Ln.10000@BT VoIP) to <sip:246@192.168.###.24:5060>
    19:19:54.109 [CM503012]: Inbound out-of-office hours rule (unnamed) for 10000 forwards to DN:246
    19:19:54.094 Looking for inbound target: called=+4415##32###6; caller=+4479##89##58
    19:19:54.078 [CM500002]: Info on incoming INVITE:
    INVITE sip:4415##32###6@192.168.###.24:5060 SIP/2.0
    Via: SIP/2.0/UDP 62.239.###.204:5060;branch=z9hG4bKsu5isd303grgu7lup581.1
    Max-Forwards: 27
    Contact: <sip:+4479##89##58@62.239.###.204:5060;transport=udp>
    To: "+4415##32###6"<sip:+4415##32###6@10.16.###.180:5060;user=phone>
    From: <sip:+4479##89##58@10.192.###.17:5060;user=phone>;tag=SDim86c01-0082-00003a42-0ec4
    Call-ID: SDim86c01-498f1532d58572889946fa0a8b46b20e-uprdb62
    CSeq: 1 INVITE
    Session-Expires: 900
    Min-SE: 450
    Allow: INVITE, ACK, BYE, CANCEL, UPDATE
    Supported: timer
    Content-Length: 0
    P-Charging-Vector: icid-value=3958NrOoTDX4y1sJ60F1303755428@vpsle42b
    P-DCS-Billing-Info: 4db5baa4ecfa37f6@62.239.###.228
    P-Presented-Identity: <sip:unknown@unknown.invalid>

     
  4. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,582
    Likes Received:
    249
    You may want to make use of Wireshark to see what is being sent by your provider, and when. This site has a very good "basic" call flow chart. You would need to compare this (the messaging) to what you see in Wireshark and where the delay is occurring. http://technet.microsoft.com/en-us/library/bb457036.aspx
     
  5. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,582
    Likes Received:
    249
    Haven't seen this sort of log before. Is this a DID trunk? It looks to be sending a "to" number.
     
  6. red4

    Joined:
    Feb 19, 2010
    Messages:
    8
    Likes Received:
    0
    The provider is a VoIP trunk from BT

    Below is the output from Wireshark
    BTSIP.BT.COM is the SIP server address.

    Code:
    Time          Source           Destination       Type      Info
    0.000000000	62.239.###.204	192.168.###.24	 SIP/SDP	Request: INVITE sip:4415##32###6@192.168.###.24:5060, with session description
    0.018169000	192.168.###.24	192.168.###.255	NBNS      Name query NB BTSIP.BT.COM<00>
    0.098084000	192.168.###.24	62.239.###.204	 SIP	    Status: 100 Trying
    0.761686000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    1.510656000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    2.260619000	192.168.###.24	192.168.###.255	NBNS      Name query NB BTSIP.BT.COM<00>
    3.003543000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    3.753621000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    4.504978000	192.168.###.24	stunserver.siptesting.net	CLASSIC-STUN	Message: Binding Request
    4.518970000	192.168.###.24	stunserver.siptesting.net	CLASSIC-STUN	Message: Binding Request
    4.667366000	stunserver.siptesting.net	192.168.###.24	CLASSIC-STUN	Message: Binding Response
    4.683045000	stunserver.siptesting.net	192.168.###.24	CLASSIC-STUN	Message: Binding Response
    4.687212000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    5.426310000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    6.176118000	192.168.###.24	192.168.###.255	NBNS	   Name query NB BTSIP.BT.COM<00>
    7.105444000	192.168.###.24	192.168.###.105	SIP/SDP	Request: INVITE sip:246@192.168.###.105:5060, with session description
    7.118183000	192.168.###.105	192.168.###.24	SIP	    Status: 100 Trying
    7.167755000	192.168.###.105	192.168.###.24	SIP	    Status: 180 Ringing
    7.270139000	192.168.###.24	62.239.###.204	 SIP	    Status: 180 Ringing
     
  7. red4

    Joined:
    Feb 19, 2010
    Messages:
    8
    Likes Received:
    0
    OK, I think this is possibly the fault:

    192.168.###.24 192.168.###.255 NBNS Name query NB BTSIP.BT.COM<00>

    Any idea how to stop this as it runs several times and each one delays the connection for 1 second.
     
  8. red4

    Joined:
    Feb 19, 2010
    Messages:
    8
    Likes Received:
    0
    I have managed to remove the delay from incoming calls.
    The delay is now between 0.727 and 1.25 seconds between INVITE and RINGING which is perfect.

    SOLUTION
    As the server is on a static IP some settings need to be set manually that are normally done by the DHCP server.
    The "Name query NB BTSIP.BT.COM" was removed by turning off the NETBios on the network card (Under IPv4>Advanced>Wins)




    Thanks leejor, without WireShark I would never have found the issue.
     
  9. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,582
    Likes Received:
    249
    Is the repeated name query because there was no connection to a DNS server and it finally gave up (timed out)?
     
  10. red4

    Joined:
    Feb 19, 2010
    Messages:
    8
    Likes Received:
    0
    The server has access to two Windows Server 2008 DNS servers and the router as a DNS server.

    DNS#1: 192.168.###.20
    DNS#2: 192.168.###.21
    DNS#3: 192.168.###.254 (Router)

    But the call was always being made to the broadcast address. (192.168.###.255)
     
Thread Status:
Not open for further replies.