Bizarre Issue

[dhogg]

Hi all,

I'm in the process of deploying 3cx-64 Pro to replace the old Alcatel ISDN based system in my business. There have been a number of challenges (primarily because of Gamma, a UK based SIP provider who use the VIA IP address to authenticate your server) however we are finally near the go-live date.

Recently I've encountered a new issue when calling internally. We're using a combination of Yealink T22p handsets (107) and a number of softphone only users. The issue is as follows:

All Yealink handsets can dial each other
All softphones can dial each other
All extensions can connect to external numbers

Several users (including my own extension) cannot call Yealink handsets from the 3cx Windows Phone. When I dial 2128 (first extension I noticed this issue with) there is a period of approximately 4-5 seconds then I'm automatically diverted to voicemail. If I change the active account on my 3cx Windows Phone to one of the other extensions I can then call 2128 as normal with instant connection.

I have observed that all of the IT staff extensions cannot dial 2128. I created a new extension with no custom configuration and it also could not dial 2128.

My iPhone 6 3cx v12 app can dial 2128 and connect immediately even from a WAN link.

* The phone isn't being used, I brought it back to my desk to work on and it is in a permanent state of idle with no active calls to prevent connection.
* None of these extensions/connections are external at this time. I'm still finalising testing of internal use with the assistance of 20 or so test subjects.
* The PBX, softphones and Yealink handsets are all on the same layer 2 network.

Anyone experienced anything similar? Tried Googling all sorts of search terms but it's a very hard issue to pin down with a conclusive summary.

I am fairly new to SIP/VoIP so if you require more logs/information please don't hesitate to ask.

Many thanks
David

 

[lneblett]

It would be really helpful if you would post the log of a failed call so we can possibly see the reason.

While you indicated the extension number that could not be reached, it may also be helpful to know the extension number from which you called and it failed and then again the extension you changed to when it worked. You also mentioned that the entire IT group could not reach 2128.

The log will likely provide some meaningful insight. To confirm:

1. All the SIP endpoints show to be registered on the system?
2. Does Ext.2128 have any exceptions programmed into the system?
3. All the endpoints are on the same internal LAN subnet along with the 3CX system?
4. Is there any VLAN within the network? (this is where I am a little suspicious). The softphone does not support VLAN natively. Presumably it will pick up the tagging that is done at the NIC level or possibly the port on the switch. I thought this had a high probability of being the issue, then you had to go and throw in the notion that merely changing the account to a different extension on the softphone allowed the call to go thru.

 

[dhogg]

Hi lneblett,

1) Indeed; all phones show as properly registered both Yealink units and 3cx Windows phones.
2) I'm inclined to say no but not spent enough time with 3cx to know exactly what you're referring to, being brutally honest.
3) Indeed, all on the same /24 layer 2 network.
4) There are two VLANs in use for other purposes - specifically the WiFi APs and to allow the unusual WAN interface connectivity specified above. These VLANs aren't accessible outside of the ports specifically connected to the equipment listed above and every other port is set to default (0) untagged.

This is the output from the server log when I try to call 2128 from 1191 (my own extension):


07-Dec-2014 16:41:07.693 [CM503007]: Call(C:1): VMail:8000 has joined, contact <sip:[email protected]:40600>
07-Dec-2014 16:41:07.693 [CM503007]: Call(C:1): Extn:1191 has joined, contact <sip:[email protected]:56095>
07-Dec-2014 16:41:07.692 L:1.3[VMail] has joined to L:1.1[Extn]
07-Dec-2014 16:41:07.549 [CM503025]: Call(C:1): Calling T:VMail:8000@[Dev:sip:[email protected]:40600;rinstance=4cca989e17db8dd0] for L:1.1[Extn]
07-Dec-2014 16:41:07.497 [CM503005]: Call(C:1): Forwarding: T:VMail:8000@[Dev:sip:[email protected]:40600;rinstance=4cca989e17db8dd0]
07-Dec-2014 16:41:07.497 L:1.1[Extn] forwards call from Extn:2128 to VMail:8000 based on rule Fwd[Available/NoAnsw]
07-Dec-2014 16:41:07.497 L:1.1[Extn] failed to reach Extn:2128, reason No Answer
07-Dec-2014 16:40:49.426 Currently active calls - 1: [1]
07-Dec-2014 16:40:47.461 [CM503025]: Call(C:1): Calling T:Extn:2128@[Dev:sip:[email protected]:5062] for L:1.1[Extn]
07-Dec-2014 16:40:47.409 [CM503027]: Call(C:1): From: Extn:1191 ("1191" <sip:[email protected]:5060>) to T:Extn:2128@[Dev:sip:[email protected]:5062]
07-Dec-2014 16:40:47.409 [CM503004]: Call(C:1): Route 1: from L:1.1[Extn] to T:Extn:2128@[Dev:sip:[email protected]:5062]
07-Dec-2014 16:40:47.406 [CM503001]: Call(C:1): Incoming call from Extn:1191 to <sip:[email protected]:5060>
07-Dec-2014 16:40:39.046 [CM504001]: Endpoint Extn:1191: new contact is registered. Contact(s): [sip:[email protected]:56095 / 1191]


If I change to my colleague's extension (1107) this output occurs (and the phone rings as it should):


07-Dec-2014 16:42:44.553 Leg L:2.1[Extn] is terminated: Cause: BYE from PBX
07-Dec-2014 16:42:44.553 [CM503008]: Call(C:2): Call is terminated
07-Dec-2014 16:42:44.553 [CM503023]: Call(C:2): Call recording is stopped, audio file: C:\ProgramData\3CX\Data\Recordings\1107\[1107]_1107-2128_20141207164241(2).wav
07-Dec-2014 16:42:44.552 Leg L:2.2[Extn] is terminated: Cause: BYE from 192.168.0.193:5062
07-Dec-2014 16:42:41.614 [CM503007]: Call(C:2): Extn:2128 has joined, contact <sip:[email protected]:5062>
07-Dec-2014 16:42:41.614 [CM503007]: Call(C:2): Extn:1107 has joined, contact <sip:[email protected]:56095>
07-Dec-2014 16:42:41.614 [CM503022]: Call(C:2): Call recording is started, audio file: C:\ProgramData\3CX\Data\Recordings\1107\[1107]_1107-2128_20141207164241(2).wav
07-Dec-2014 16:42:41.578 L:2.2[Extn] has joined to L:2.1[Extn]
07-Dec-2014 16:42:35.843 [CM503025]: Call(C:2): Calling T:Extn:2128@[Dev:sip:[email protected]:5062] for L:2.1[Extn]
07-Dec-2014 16:42:35.794 [CM503027]: Call(C:2): From: Extn:1107 ("1107" <sip:[email protected]:5060>) to T:Extn:2128@[Dev:sip:[email protected]:5062]
07-Dec-2014 16:42:35.794 [CM503004]: Call(C:2): Route 1: from L:2.1[Extn] to T:Extn:2128@[Dev:sip:[email protected]:5062]
07-Dec-2014 16:42:35.793 [CM503001]: Call(C:2): Incoming call from Extn:1107 to <sip:[email protected]:5060>
07-Dec-2014 16:42:14.662 [CM504001]: Endpoint Extn:1107: new contact is registered. Contact(s): [sip:[email protected]:56095 / 1107]

Hope this helps. If you need anything else let me know.

PS - when I ring 2128 from my own extension - just before the call fails the line LEDs on the 2128 handset flash green once.

Many thanks
David

 

[leejor]

07-Dec-2014 16:41:07.497 L:1.1[Extn] failed to reach Extn:2128, reason No Answer
07-Dec-2014 16:40:49.426 Currently active calls - 1: [1]
07-Dec-2014 16:40:47.461 [CM503025]: Call(C:1): Calling T:Extn:2128@[Dev:sip:[email protected]:5062] for L:1.1[Extn]

07-Dec-2014 16:42:41.614 [CM503007]: Call(C:2): Extn:1107 has joined, contact <sip:[email protected]:56095>
07-Dec-2014 16:42:41.614 [CM503022]: Call(C:2): Call recording is started, audio file: C:\ProgramData\3CX\Data\Recordings\1107\[1107]_1107-2128_20141207164241(2).wav
07-Dec-2014 16:42:41.578 L:2.2[Extn] has joined to L:2.1[Extn]
07-Dec-2014 16:42:35.843 [CM503025]: Call(C:2): Calling T:Extn:2128@[Dev:sip:[email protected]:5062] for L:2.1[Extn]

There is a 20 second delay on the failed call, is that the delay time set in Ext 2128 before forwarding to VM?

The obvious difference is that there is call recording involved on the second call from 1107. Have you tried turning that on (or off) on ext 1191?

Using the Verbose setting, in the logs may give additional information when doing a comparison of a failed and a successful call.

 

[tsukraw]

Hey Dhogg,
So the symptom you are describing we actually actually encountered last week on a 160 extension install (100 being Yealink T46).
In our case it was a network related issue with a device causing issues in the ARP table.
Im not sure your technical level but here are a couple things you could do to try to check if this is the issue.

1) From your 3CX server do a continuous ping to a couple yealink phones. (One being to your laptop with the 3CX app, another to a yealink phone the call is not completing to). If you are seeing any dropped packets.

2)Second test. So the 2 extensions you are calling between that are not working. Go on 3CX to those extensions/Options. Check the box. "PBX Delivers Audio". This will force the SIP/RTP traffic to go Phone -> PBX -> Phone instead of the phones trying to talk to each other. If this works this could farther confirm you are seeing a similar issue to what we saw.

Do you by chance know what kind of switches you are using? Are they managed switches?

 

[cobaltit]

@dhogg

I'm going to say that your Yealink phones shipped with a v72 firmware. Downgrade them to the 3CX supported firmware and you should be all set.

 

[dhogg]

Hi folks,

Thanks for the suggestions/input - much appreciated. Turning on "PBX Delivers Audio" does fix the problem - at least a step in the right direction!

leejor

The 20 second delay is indeed set as per below:



Verbose output of a call that failed to 2128

08-Dec-2014 09:45:45.957 L:33.1[Extn]: Terminating targets, reason: SIP ;cause=200 ;text="User hangup"
08-Dec-2014 09:45:45.957 Leg L:33.1[Extn] is terminated: Cause: BYE from 192.168.0.35:59693
08-Dec-2014 09:45:45.955 L:33.1[Extn] got Terminated Recv Req BYE from 192.168.0.35:59693 tid=Pje5995dc27ebe42beb2cb22b806af8f81 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPje5995dc27ebe42beb2cb22b806af8f81
Max-Forwards: 70
To: <sip:[email protected]:5060>;tag=2b2a7a06
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23065 BYE
User-Agent: 3CXPhone for Windows 12.0.37098.0
Content-Length: 0
08-Dec-2014 09:45:45.955 L:33.1[Extn] Sending: OnSendResp Send 200/BYE from 0.0.0.0:0 tid=Pje5995dc27ebe42beb2cb22b806af8f81 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPje5995dc27ebe42beb2cb22b806af8f81
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=2b2a7a06
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23065 BYE
Content-Length: 0
08-Dec-2014 09:45:42.019 Session 56627 of leg L:33.1[Extn] is confirmed
08-Dec-2014 09:45:42.019 L:33.1[Extn] got Confirmed Recv Req ACK from 192.168.0.35:59693 tid=Pj221e9b840f9e4232b60a5b844906eb96 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPj221e9b840f9e4232b60a5b844906eb96
Max-Forwards: 70
To: <sip:[email protected]:5060>;tag=2b2a7a06
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23064 ACK
Content-Length: 0
08-Dec-2014 09:45:41.920 [CM503007]: Call(C:33): Extn:1119 has joined, contact <sip:[email protected]:59693>
08-Dec-2014 09:45:41.920 Session 56627 of leg L:33.1[Extn] is connected
08-Dec-2014 09:45:41.919 L:33.1[Extn] got Connected.UAS Send 200/INVITE from 0.0.0.0:0 tid=Pjc05d33e85030446fb179c7e670d867d7 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPjc05d33e85030446fb179c7e670d867d7
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=2b2a7a06
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23064 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
User-Agent: 3CXPhoneSystem 12.0.37098.738 (34969)
Content-Length: 295

v=0
o=3cxPS 35366371328 244678918145 IN IP4 192.168.0.4
s=3cxPS Audio call
c=IN IP4 192.168.0.4
t=0 0
m=audio 7120 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
m=video 0 RTP/AVP 31
c=IN IP4 127.0.0.1
08-Dec-2014 09:45:41.919 L:33.1[Extn] Sending: OnSendResp Send 200/INVITE from 0.0.0.0:0 tid=Pjc05d33e85030446fb179c7e670d867d7 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPjc05d33e85030446fb179c7e670d867d7
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=2b2a7a06
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23064 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REGISTER, SUBSCRIBE, NOTIFY, REFER, INFO, MESSAGE
Content-Type: application/sdp
Supported: replaces
Content-Length: 295

v=0
o=3cxPS 35366371328 244678918145 IN IP4 192.168.0.4
s=3cxPS Audio call
c=IN IP4 192.168.0.4
t=0 0
m=audio 7120 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
m=video 0 RTP/AVP 31
c=IN IP4 127.0.0.1
08-Dec-2014 09:45:41.917 L:33.1[Extn]: Terminating targets, reason: SIP ;cause=200 ;text="Call completed elsewhere"
08-Dec-2014 09:45:41.916 L:33.3[VMail] has joined to L:33.1[Extn]
08-Dec-2014 09:45:41.914 L:33.1[Extn] Sending: OnSendResp Send 180/INVITE from 0.0.0.0:0 tid=Pjc05d33e85030446fb179c7e670d867d7 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPjc05d33e85030446fb179c7e670d867d7
Contact: <sip:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=2b2a7a06
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23064 INVITE
Content-Length: 0
08-Dec-2014 09:45:41.708 [CM503025]: Call(C:33): Calling T:VMail:8000@[Dev:sip:[email protected]:40600;rinstance=bee3ac85f5b128f6] for L:33.1[Extn]
08-Dec-2014 09:45:41.648 [Flow] Call(C:33): making call from L:33.1[Extn] to T:VMail:8000@[Dev:sip:[email protected]:40600;rinstance=bee3ac85f5b128f6]
08-Dec-2014 09:45:41.648 [Flow] L:33.1[Extn]: Build targets for VMail:8000
08-Dec-2014 09:45:41.648 L:33.1[Extn] forwards call from Extn:2128 to VMail:8000 based on rule Fwd[Available/NoAnsw]
08-Dec-2014 09:45:41.647 L:33.1[Extn] failed to reach Extn:2128, reason No Answer
08-Dec-2014 09:45:21.611 [CM503025]: Call(C:33): Calling T:Extn:2128@[Dev:sip:[email protected]:5062] for L:33.1[Extn]
08-Dec-2014 09:45:21.574 [Flow] Call(C:33): making call from L:33.1[Extn] to T:Extn:2128@[Dev:sip:[email protected]:5062]
08-Dec-2014 09:45:21.574 [CM503027]: Call(C:33): From: Extn:1119 ("Test Guy" <sip:[email protected]:5060>) to T:Extn:2128@[Dev:sip:[email protected]:5062]
08-Dec-2014 09:45:21.574 [CM503004]: Call(C:33): Route 1: from L:33.1[Extn] to T:Extn:2128@[Dev:sip:[email protected]:5062]
08-Dec-2014 09:45:21.571 [Flow] Call(C:33): has built target endpoint: Extn:2128 for call from L:33.1[Extn]
08-Dec-2014 09:45:21.571 [CM503010]: Call(C:33): Making route(s) from Extn:1119 to <sip:[email protected]:5060>
08-Dec-2014 09:45:21.570 Remote SDP is set for leg L:33.1[Extn]
08-Dec-2014 09:45:21.570 [CM505001]: Endpoint Extn:1119: 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:[email protected]:5060]
08-Dec-2014 09:45:21.569 [CM500002]: Call(C:33): Info on incoming INVITE from Extn:1119:
Invite-IN Recv Req INVITE from 192.168.0.35:59693 tid=Pjc05d33e85030446fb179c7e670d867d7 Call-ID=71b87f3c73d9439fbd180406d3371e8a:
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPjc05d33e85030446fb179c7e670d867d7
Max-Forwards: 70
Contact: "Test Guy"<sip:[email protected]:59693;ob>
To: <sip:[email protected]:5060>
From: "Test Guy"<sip:[email protected]:5060>;tag=c354649a7b8e4271b91a7f955bf8c42b
Call-ID: 71b87f3c73d9439fbd180406d3371e8a
CSeq: 23064 INVITE

tsukraw

I ran a ping from the PBX to the handset of 2128 as suggested with no loss. This ping ran over about 10 hours:

Ping statistics for 192.168.0.193:
Packets: Sent = 37461, Received = 37461, Lost = 0 (0% loss),
Approximate round trip times in milli-seconds:
Minimum = 0ms, Maximum = 59ms, Average = 0ms

I also ran an overnight ping from the PBX to my machine with zero loss. In hindsight if it was an ARP issue the softphone wouldn't work regardless of extension whereas it does seem to be an extension specific issue.

With that being said - your idea to turn on "PBX Delivers Audio" immediately resolves the problem so there is an issue connecting the softphone to the handset.

cobaltit

Indeed the phones seem to have shipped with v72 firmware, I'll look into downgrading one of them and see if that corrects the issue.

SUMMARY
Thus far we've ascertained that:

* This issue is specific to certain extensions. Any newly created extensions also suffer the same issue.
* PBX Delivers Audio cures the problem suggesting there is an issue getting SIP/RTP traffic to the phone from the softphone - even more confusing given that it is extension specific (I can change to my colleague's on my own softphone and immediately call 2128)
* Vice versa works. The Yealink phone can call the problematic extension's softphone with no issues.

Many thanks
David

 

[tsukraw]

Dhogg,
What timezone are you in?
This issue has be very curious with what is the cause.
I'll shoot you a PM. If your open to it id like to jump on remotely with you and do a couple captures see if we cant nail down the cause.

 

[Pauliebrisbane]

It looks like a VLAN issue as the call works when the PBX delivers audio.

Are the phones on separate VLAN's as the RTP stream between the phones isn't being setup but the signalling link to the 3CX server is working fine.

 

[Pauliebrisbane]

Also try checking the RTP settings and codecs.

3CX Windows Client RTP Mode: Normal or Secure
3CX Windows Client Audio Codecs: PCMU, G.722 etc.

I haven't setup a Yealink handset yet, but look for these setting in the phone to ensure they can both negotiate the same codec, you may need to prioritize different codecs in case a bug is causing problems with a particular codec.