10 second delay in connecting

[Orgs]

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

==================================================================================================

09:27:00.347|.\Call.cpp(479)|Trace5||Call::MakeCall:MakeCall from C:1.1 to VoIPline:02089716810@(Ln.10000@VoIPOn)@[Dev:sip:[email protected]: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:[email protected]: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 [email protected]: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:[email protected]:5060;rinstance=498f893e8ae71909 SIP/2.0
Via: SIP/2.0/UDP 217.14.138.154:5065;branch=0
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=fbea59c5
Call-ID: [email protected]
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 [email protected]: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:[email protected]:5060;rinstance=498f893e8ae71909 SIP/2.0
Via: SIP/2.0/UDP 217.14.138.154:5065;branch=0
To: <sip:[email protected]>
From: <sip:[email protected]>;tag=fbea59c5
Call-ID: [email protected]
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:[email protected]>
From: <sip:[email protected]>;tag=fbea59c5
Call-ID: [email protected]
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:[email protected]: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:

 

[mfm]

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.

 

[Orgs]

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

 

[leejor]

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).

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?

 

[Orgs]

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.