10 second delay in connecting

Discussion in '3CX Phone System - General' started by Orgs, Sep 6, 2010.

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

    Joined:
    Aug 2, 2010
    Messages:
    3
    Likes Received:
    0
    Hi there... we are looking at replacing out Nortel PBX with 3CX and I cannot work out why (well how to fix) a problem with both inbound and outbound calls. Both work fine, sound quality is stunning, everything I have ever wanted from a phone system. The only problem is that we have around a 9-10 second delay while 3CX has some issues.

    3CX is running on Windows XP in a Hyper-V virtual machine with a is Microsoft TMG firewall, which I upgraded from ISA as I could not get that to work at all.

    I have pasted an excerpt of the 3CX log at the bottom, hopefully there is a clue in there that I cannot see...

    One final thing... I turned off STUN as we have a fixed IP available for 3CX and inbound calls connected immediately, but I could not make any outbound calls at all...

    Any clues would be gratefully accepted and I am very keen to roll out 3CX to all our users ASAP and decommission the Nortel.

    Many thanks in advance...
    Chris

    ==================================================================================================
    Code:
    09:27:00.347|.\Call.cpp(479)|Trace5||Call::MakeCall:MakeCall from C:1.1 to VoIPline:02089716810@(Ln.10000@VoIPOn)@[Dev:sip:7278929@sip.voipon.co.uk:5060]
    09:27:00.363|.\Call.cpp(189)|Trace5||Call::addLeg:Adding leg C:0.0
    09:27:00.363|.\Call.cpp(232)|Trace5||Call::addLeg:Legs count: 2
    09:27:00.363|.\SLAIface.cpp(221)|Debug2||SLAMgr::acquireSlot:SLA is not enabled for DN 10000
    09:27:00.363|.\CallLeg.cpp(1988)|Debug2||??:SLA slot is acquired: 10000#0 'idle'
    09:27:00.363|.\CallLeg.cpp(930)|Trace5||CallLeg::getOutboundHost:Outbound URI is used: sip:7278929@217.14.138.127:5060
    09:27:03.409|.\Transport.cxx(287)|Debug8|Resip|::ResipLogger:incoming from: [ V4 217.14.138.154:5065 UDP target domain=unspecified mFlowKey=768 ]
    09:27:03.409|.\TransactionUser.cxx(66)|Debug8|Resip|::ResipLogger:Checking if SipReq:  OPTIONS 7278929@213.121.243.220:5060 tid=4927d51777b78700e4ff37201db6aa91 cseq=OPTIONS / 1 from(wire) is for me
    09:27:03.409|.\TransactionUser.cxx(71)|Debug8|Resip|::ResipLogger:Checking rule...
    09:27:03.409|.\MessageFilterRule.cxx(42)|Debug8|Resip|::ResipLogger:Matching rule for: 
    
    OPTIONS sip:7278929@213.121.243.220:5060;rinstance=498f893e8ae71909 SIP/2.0
    Via: SIP/2.0/UDP 217.14.138.154:5065;branch=0
    To: <sip:7278929@voiptalk.org>
    From: <sip:vnt-10@voiptalk.org>;tag=fbea59c5
    Call-ID: c8734294-27cfa423-4aeee3@217.14.138.154
    CSeq: 1 OPTIONS
    Content-Length: 0
    
    
    09:27:03.409|.\TransactionUser.cxx(74)|Debug8|Resip|::ResipLogger:Match!
    09:27:03.409|.\Helper.cxx(375)|Debug8|Resip|::ResipLogger:Helper::makeResponse(SipReq:  OPTIONS 7278929@213.121.243.220:5060 tid=4927d51777b78700e4ff37201db6aa91 cseq=OPTIONS / 1 from(wire) code=100 reason=
    09:27:03.409|.\TimerQueue.cxx(85)|Debug8|Resip|::ResipLogger:Adding timer: Timer Trying tid=4927d51777b78700e4ff37201db6aa91 ms=3500
    09:27:03.409|.\TransactionState.cxx(2112)|Debug8|Resip|::ResipLogger:Send to TU: TU: DialogUsageManager size=0 
    
    OPTIONS sip:7278929@213.121.243.220:5060;rinstance=498f893e8ae71909 SIP/2.0
    Via: SIP/2.0/UDP 217.14.138.154:5065;branch=0
    To: <sip:7278929@voiptalk.org>
    From: <sip:vnt-10@voiptalk.org>;tag=fbea59c5
    Call-ID: c8734294-27cfa423-4aeee3@217.14.138.154
    CSeq: 1 OPTIONS
    Content-Length: 0
    
    
    09:27:03.409|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:03.409|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS101005] STUN request failed for ports 9000,9001 on STUN server 'stun.3cx.com:3478'
    09:27:03.409|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:03.409|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS201000] Use STUN server 'stun2.3cx.com:3478'
    09:27:05.706|.\Call.cpp(42)|Log3||??:Currently active calls - 1: [1]
    09:27:06.456|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:06.456|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS101005] STUN request failed for ports 9000,9001 on STUN server 'stun2.3cx.com:3478'
    09:27:06.456|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:06.456|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS201000] Use STUN server 'stun3.3cx.com:3478'
    09:27:06.925|.\TransportSelector.cxx(940)|Debug8|Resip|::ResipLogger:Transmitting to [ V4 217.14.138.154:5065 UDP target domain=unspecified mFlowKey=768 ] tlsDomain= via [ V4 10.1.195.90:5060 UDP target domain=unspecified mFlowKey=768 ]
    
    SIP/2.0 100 Trying
    Via: SIP/2.0/UDP 217.14.138.154:5065;branch=0
    To: <sip:7278929@voiptalk.org>
    From: <sip:vnt-10@voiptalk.org>;tag=fbea59c5
    Call-ID: c8734294-27cfa423-4aeee3@217.14.138.154
    CSeq: 1 OPTIONS
    Content-Length: 0
    
    
    09:27:06.925|.\Transport.cxx(213)|Debug8|Resip|::ResipLogger:Adding message to tx buffer to: [ V4 217.14.138.154:5065 UDP target domain=unspecified mFlowKey=768 ]
    09:27:09.503|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:09.503|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS101005] STUN request failed for ports 9000,9001 on STUN server 'stun3.3cx.com:3478'
    09:27:09.503|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:09.503|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS201000] Use STUN server 'stun.3cx.com:3478'
    09:27:09.503|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:09.503|.\SLServer.cpp(767)|Error1|MediaServer|MediaServerReporting::STUN:[MS101003] C:1.2: Possible firewall problem. Address mapping failed on STUN server 96.9.132.83:3478 for local address "213.121.243.220:9000"
    09:27:09.628|.\MSInterface.cpp(682)|Trace5||??:MSLogReports
    09:27:09.628|.\SLServer.cpp(823)|Log5|MediaServer|MediaServerReporting::SetRemoteParty:[MS210002] C:1.2:Offer provided. Connection(transcoding mode): 10.1.195.90:9000(9001)
    09:27:09.628|.\UserProfile.cxx(135)|Debug8|Resip|::ResipLogger:Adding credential: realm=3CXPhoneSystem user=7278929
    09:27:09.628|.\DevsMgr.cpp(252)|Trace5||Device::updateTransport:Updating device
    09:27:09.628|.\DevsMgr.cpp(89)|Trace5||Device::update:Resolving outbound host: sip.voipon.co.uk
    09:27:09.660|.\DevsMgr.cpp(94)|Trace5||Device::update:Outbound host is resolved to: 217.14.138.127
    09:27:09.660|.\DevsMgr.cpp(195)|Trace5||Device::update:PBX contact is global Public IP: sip:7278929@213.121.243.220:5060
    09:27:09.660|.\Line.cpp(1315)|Debug2||Line::feedSourceLeg:OutCID: ''; OutName: 'Chris Morgan'
    09:27:09.675|.\BaseCreator.cxx(155)|Debug8|Resip|::ResipLogger:BaseCreator::makeInitialRequest:
     
  2. mfm

    mfm Active Member

    Joined:
    Mar 4, 2010
    Messages:
    641
    Likes Received:
    2
    Hi Orgs,

    From your logs, I can clearly see that as soon as the invite is recieved by 3cx it is processed within milliseconds. Having said that, altough you have set you system to stunless ( im not sure when these logs were copied) it is showing errors in disvocering the stun adress.

    1. Run the firewall checker in settings > firewall checker. You will have to stop the tunnel service and phone system service to do so.

    2. Please clarify where the delay is, audio delay, delay to call. And the phones you are using.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  3. Orgs

    Joined:
    Aug 2, 2010
    Messages:
    3
    Likes Received:
    0
    Mark,

    Sorry I may not have been as clear at I could have... I set the system to be STUNless, as I could see the errors, but I could not get the system to make an outbound call at all, so I have changed it back to STUN mode.

    I agree the system is processing the call within microseconds, but when we get the "STUN request failed for ports 9000,9001 on STUN server 'stun.3cx.com:3478'" errors there roughly a 2 second delay, which happens a few times.

    Running the firewall checker this is as far as it gets ... which I do realise is not correct, but I can (and I am) making and receiving calls very happily, even with the delay.

    3CX Firewall Checker, v1.0. Copyright (C) 3CX Ltd. All rights reserved.

    <13:36:34>: Phase 1, checking servers connection, please wait...
    <13:36:34>: Stun Checker service is reachable. Phase 1 check passed.
    <13:36:34>: Phase 2a, Check Port Forwarding to UDP SIP port, please wait...
    <13:36:47>: UDP SIP Port is set to 5060. NO RESPONSE received. Phase 2a check FAILED.

    Application exit code is -2

    The delay is after I dial the number (by pressing the "Tick") and before the receiving phone starts to ring (both are on my desk).

    I am using a SNOM821.

    Finally I should have said this before... I can see all the traffic passing through the firewall without any denies or errors...

    Chris
     
  4. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,869
    Likes Received:
    304
    Could this be caused by the phone not sending the digits immediately to 3CX, a set option that needs "correcting"? Most VoIP sets will wait a predetermined time (usually 4 to 5 seconds) after the last digit has been dialled before sending, or, you have to dial #,to send immediately, or, you need to define a dialplan in the set.

    Haven't used that particular set, is the "tick" key a "send" key?
     
  5. Orgs

    Joined:
    Aug 2, 2010
    Messages:
    3
    Likes Received:
    0
    Have gone through every screen, including the dial delay setting (its hard to believe that each phone has so many settings, maybe more than some traditional pbx switches), but it is set to 5 seconds.

    My timings are from the logs rather than from my interactions with a phone (soft or hard)... but a good thought though.

    Thanks.
     
Thread Status:
Not open for further replies.