Bizarre Issue

Discussion in '3CX Phone System - General' started by dhogg, Dec 7, 2014.

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

    Joined:
    Nov 10, 2014
    Messages:
    7
    Likes Received:
    0
    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
     
  2. lneblett

    lneblett Well-Known Member

    Joined:
    Sep 7, 2010
    Messages:
    2,061
    Likes Received:
    56
    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.
     
  3. dhogg

    Joined:
    Nov 10, 2014
    Messages:
    7
    Likes Received:
    0
    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:8000@127.0.0.1:40600>
    07-Dec-2014 16:41:07.693 [CM503007]: Call(C:1): Extn:1191 has joined, contact <sip:1191@192.168.0.30: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:8000@127.0.0.1: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:8000@127.0.0.1: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:2128@192.168.0.193:5062] for L:1.1[Extn]
    07-Dec-2014 16:40:47.409 [CM503027]: Call(C:1): From: Extn:1191 ("1191" <sip:1191@192.168.0.4:5060>) to T:Extn:2128@[Dev:sip:2128@192.168.0.193: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:2128@192.168.0.193:5062]
    07-Dec-2014 16:40:47.406 [CM503001]: Call(C:1): Incoming call from Extn:1191 to <sip:2128@192.168.0.4:5060>
    07-Dec-2014 16:40:39.046 [CM504001]: Endpoint Extn:1191: new contact is registered. Contact(s): [sip:1191@192.168.0.30: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:2128@192.168.0.193:5062>
    07-Dec-2014 16:42:41.614 [CM503007]: Call(C:2): Extn:1107 has joined, contact <sip:1107@192.168.0.30: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:2128@192.168.0.193:5062] for L:2.1[Extn]
    07-Dec-2014 16:42:35.794 [CM503027]: Call(C:2): From: Extn:1107 ("1107" <sip:1107@192.168.0.4:5060>) to T:Extn:2128@[Dev:sip:2128@192.168.0.193: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:2128@192.168.0.193:5062]
    07-Dec-2014 16:42:35.793 [CM503001]: Call(C:2): Incoming call from Extn:1107 to <sip:2128@192.168.0.4:5060>
    07-Dec-2014 16:42:14.662 [CM504001]: Endpoint Extn:1107: new contact is registered. Contact(s): [sip:1107@192.168.0.30: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
     
  4. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    10,374
    Likes Received:
    231
    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.
     
  5. tsukraw

    tsukraw New Member

    Joined:
    Mar 9, 2012
    Messages:
    190
    Likes Received:
    6
    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?
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  6. cobaltit

    cobaltit Active Member

    Joined:
    Mar 22, 2012
    Messages:
    736
    Likes Received:
    113
    @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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  7. dhogg

    Joined:
    Nov 10, 2014
    Messages:
    7
    Likes Received:
    0
    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:2128@192.168.0.4:5060 SIP/2.0
    Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPje5995dc27ebe42beb2cb22b806af8f81
    Max-Forwards: 70
    To: <sip:2128@192.168.0.4:5060>;tag=2b2a7a06
    From: "Test Guy"<sip:1119@192.168.0.4: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:2128@192.168.0.4:5060>
    To: <sip:2128@192.168.0.4:5060>;tag=2b2a7a06
    From: "Test Guy"<sip:1119@192.168.0.4: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:2128@192.168.0.4:5060 SIP/2.0
    Via: SIP/2.0/UDP 192.168.0.35:59693;rport=59693;branch=z9hG4bKPj221e9b840f9e4232b60a5b844906eb96
    Max-Forwards: 70
    To: <sip:2128@192.168.0.4:5060>;tag=2b2a7a06
    From: "Test Guy"<sip:1119@192.168.0.4: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:1119@192.168.0.35: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:2128@192.168.0.4:5060>
    To: <sip:2128@192.168.0.4:5060>;tag=2b2a7a06
    From: "Test Guy"<sip:1119@192.168.0.4: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:2128@192.168.0.4:5060>
    To: <sip:2128@192.168.0.4:5060>;tag=2b2a7a06
    From: "Test Guy"<sip:1119@192.168.0.4: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:2128@192.168.0.4:5060>
    To: <sip:2128@192.168.0.4:5060>;tag=2b2a7a06
    From: "Test Guy"<sip:1119@192.168.0.4: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:8000@127.0.0.1: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:8000@127.0.0.1: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:2128@192.168.0.193: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:2128@192.168.0.193:5062]
    08-Dec-2014 09:45:21.574 [CM503027]: Call(C:33): From: Extn:1119 ("Test Guy" <sip:1119@192.168.0.4:5060>) to T:Extn:2128@[Dev:sip:2128@192.168.0.193: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:2128@192.168.0.193: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:2128@192.168.0.4: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:1119@192.168.0.4: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:2128@192.168.0.4: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:1119@192.168.0.35:59693;ob>
    To: <sip:2128@192.168.0.4:5060>
    From: "Test Guy"<sip:1119@192.168.0.4: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
     

    Attached Files:

  8. tsukraw

    tsukraw New Member

    Joined:
    Mar 9, 2012
    Messages:
    190
    Likes Received:
    6
    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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  9. Pauliebrisbane

    Joined:
    Nov 14, 2014
    Messages:
    17
    Likes Received:
    0
    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.
     
  10. Pauliebrisbane

    Joined:
    Nov 14, 2014
    Messages:
    17
    Likes Received:
    0
    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.
     
Thread Status:
Not open for further replies.