Dismiss Notice
We would like to remind you that we’re updating our login process for all 3CX forums whereby you will be able to login with the same credentials you use for the Partner or Customer Portal. Click here to read more.

Cisco SPA504g always busy or not available

Discussion in '3CX Phone System - General' started by Mike MSTG, Jan 8, 2014.

Thread Status:
Not open for further replies.
  1. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    I'm not sure if this is a problem with how the phones have gotten provisioned or some other setting we are missing however we have every phone in our office giving the same response in the logs:
    8-Jan-2014 16:13:19.844 Leg L:27.3[Extn] is terminated: Cause: 486 Busy Here/INVITE from .....
    08-Jan-2014 16:13:19.844 L:27.1[Line:89999<<...] failed to reach Extn:2025, reason Busy

    On the phone side of things, the phone does happen to ring but only once and its more of a half-ring that lasts less than a second.

    And if that failed, this happens:
    08-Jan-2014 16:13:27.658 L:28.1[Extn] failed to reach Line:89999>>1723420300, reason Server Failure
    08-Jan-2014 16:13:27.658 Call to T:Line:89999>>1723420300@[Dev:sip:9999999999@xxxx:5060] from L:28.1[Extn] failed, cause: Cause: 503 Service Unavailable/INVITE from xxxxx:5060
    08-Jan-2014 16:13:27.658 [CM503003]: Call(C:28): Call to <sip:999999@xxxxx:5060> has failed; Cause: 503 Service Unavailable/INVITE from xxxxxx:5060

    Phones do not have DND set. We have upgraded the firmware to the latest version of 7.5.5 on the phones as well as up to date on the PBX v12 SP3 as well as the provisioning rules. We have restarted all services several times and outgoing calls are not a problem. Does anyone know what the cause of this may be?
     
  2. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,073
    Likes Received:
    323
    I'm not sure if it applies in your case, but, are the extensions set to allow more than one call?

    On occasion I have seen, in the 3CX extension settings, that for some reason, in the settings, the set shows as unavailable ( believe that is the term used), even though the set is registered and not a member of a queue.
     
  3. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    Yes, they are. I did enable the "more than 1 call" in the forwarding rules as well as set the "ALLOWUSEBUSYOPTFORGROUP" custom parameter to 1. I have no call queues.

    If you mean if they are registered, they are. Also the user status is set as Available. And I made sure each extension is not disabled.
     
  4. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,073
    Likes Received:
    323
    If you try a test call while watching the status of the set you are calling, and it was showing as idle, then as the log would tend to be indicating, a message is coming back from the set telling 3CX that it is not available.

    That being the case, it would make sense that it is either a firmware issue (probably not), or a settings issue (more likely).

    I'm not sure if that particular set has a syslog server option, but if you've gone over all of the settings, and you do have the availability of using syslog, that would at least tell you, from the phones point of view, what is going on. From that you should be able to figure out what setting is incorrect, maybe something like... call forwarding being active to a non-existent route.
     
  5. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    If the phone is being auto provisioned by 3cx, wouldn't that make 3cx the issue?

    I looked on the set and could not find any additional logging options. I'm still feeling like this is on the 3cx side of things because we only recently got these phones. Previously, we were using the 3cx soft phone and while it did work, at times it also gave the following:
    08-Jan-2014 17:14:45.934 Leg L:7.6[Extn] is terminated: Cause: 503 Service Unavailable/INVITE from local
    08-Jan-2014 17:14:45.934 L:7.1[Line:89999<<......] failed to reach Extn:2045, reason Server Failure
     
  6. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    Something else and I'm not sure if this is a clue or not, but the provisioned phones are listed twice for the same extension, only with port 5060 and 5061 as the difference.
     
  7. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    I managed to do capture syslog off the phone and this is what I captured for the call that fails:

    +++++ find idle call i = 0, caid=0 (asked 0)
    [0]CC:NewCallState 10/0

    [CCTRL]record lcr phone=xxxxxxxxxx exten=0 type=0
    START_RING in CC_refresh
    START_RING in CC_refresh
    In InitRemoteVoipMetrics
    In InitVoipMetrics
    [0]AUD ALLOC CALL (port=16460)
    [0]->xxx.xxx.1.2:5060{397)
    SIP/2.0 180 Ringing
    To: <sip:2045@xxx.xxx.1.5>;tag=47b68e3a827087bbi0
    From: <sip:xxxxxxxxxx@xxx.xxx.1.2:5060;nf=e>;tag=1f69f56d
    Call-ID: ZTBiNWY4ZjRlM2JkZmRkNWIxZDM0MmQ0ZDRkZDkwNDI.
    CSeq: 1 INVITE
    Via: SIP/2.0/UDP xxx.xxx.1.2:5060;branch=z9hG4bK-d8754z-8e22e905e34bde5e-1---d87
    54z-
    Contact: "xxxxxxxxxxx" <sip:2045@xxx.xxx.1.71:5060>
    Server: Cisco/SPA504G-7.5.5
    Content-Length: 0


    [0]<<xxx.xxx.1.2:5060
    CANCEL sip:2045@xxx.xxx.1.71:5060 SIP/2.0
    Via: SIP/2.0/UDP xxx.xxx.1.2:5060;branch=z9hG4bK-d8754z-8e22e905e34bde5e-1---d87
    54z-;rport
    Max-Forwards: 70
    To: <sip:2045@xxx.xxx.1.5>
    From: <sip:xxxxxxxxxx@xxx.xxx.1.2:5060;nf=e>;tag=1f69f56d
    Call-ID: ZTBiNWY4ZjRlM2JkZmRkNWIxZDM0MmQ0ZDRkZDkwNDI.
    CSeq: 1 CANCEL
    User-Agent: 3CXPhoneSystem 12.0.33517.465 (33463)
    Reason: SIP ;cause=486 ;text="Busy Here"
    Content-Length: 0


    [0]->xxx.xxx.1.2:5060{349)
    SIP/2.0 487 Request Terminated
    To: <sip:2045@xxx.xxx.1.5>;tag=47b68e3a827087bbi0
    From: <sip:xxxxxxxxxx@xxx.xxx.1.2:5060;nf=e>;tag=1f69f56d
    Call-ID: ZTBiNWY4ZjRlM2JkZmRkNWIxZDM0MmQ0ZDRkZDkwNDI.
    CSeq: 1 INVITE
    Via: SIP/2.0/UDP xxx.xxx.1.2:5060;branch=z9hG4bK-d8754z-8e22e905e34bde5e-1---d87
    54z-
    Server: Cisco/SPA504G-7.5.5
    Content-Length: 0


    [0]->xxx.xxx.1.2:5060{333)
    SIP/2.0 200 OK
    To: <sip:2045@xxx.xxx.1.5>;tag=47b68e3a827087bbi0
    From: <sip:xxxxxxxxxx@xxx.xxx.1.2:5060;nf=e>;tag=1f69f56d
    Call-ID: ZTBiNWY4ZjRlM2JkZmRkNWIxZDM0MmQ0ZDRkZDkwNDI.
    CSeq: 1 CANCEL
    Via: SIP/2.0/UDP xxx.xxx.1.2:5060;branch=z9hG4bK-d8754z-8e22e905e34bde5e-1---d87
    54z-
    Server: Cisco/SPA504G-7.5.5
    Content-Length: 0


    [0]AUD Rel Call
    [CCTRL]record lcr phone=xxxxxxxxxx exten=0
    [0]CC:NewCallState 0/10

    [0]<<xxx.xxx.1.2:5060
    ACK sip:2045@xxx.xxx.1.71:5060 SIP/2.0
    Via: SIP/2.0/UDP xxx.xxx.1.2:5060;branch=z9hG4bK-d8754z-8e22e905e34bde5e-1---d87
    54z-;rport
    Max-Forwards: 70
    To: <sip:2045@xxx.xxx.1.5>;tag=47b68e3a827087bbi0
    From: <sip:xxxxxxxxxx@xxx.xxx.1.2:5060;nf=e>;tag=1f69f56d
    Call-ID: ZTBiNWY4ZjRlM2JkZmRkNWIxZDM0MmQ0ZDRkZDkwNDI.
    CSeq: 1 ACK
    Content-Length: 0


    DLG Terminated
    Sess Terminated
    CC:Clean Up
    --- OBJ POOL STAT ---
    OP:? = 0 ( 8 1328)
     
  8. lneblett

    lneblett Well-Known Member

    Joined:
    Sep 7, 2010
    Messages:
    2,086
    Likes Received:
    64
    Look to see if DND (do not Disturb) on the phone itself has been accidentally turned on.

    What will normally happen in this instance is that the phone is set, but not 3CX. As a result, when a call comes in 3CX does not know that the phone is set to DND so it tries to send the call to the extension. The phone may ring once or even give a partial ring while at the same time responding back to 3CX with (typically) a busy here (486) code. 3CX will then handle according to the rules for a busy condition.
     
  9. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    It's not. I've even tried setting and clearing with no luck.

    When it is set, it does exactly what is expected - straight to voice mail, phone does not ring at all. When DND is not set, the phone will ring but will only do a half ring (less than one second really) and then off to voice mail. It's obvious the phone is getting the incoming call but why does it stop? That's where I'm confused...
     
  10. gschwab

    gschwab New Member

    Joined:
    Mar 21, 2012
    Messages:
    131
    Likes Received:
    0
    My next step would be to try another phone
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  11. lneblett

    lneblett Well-Known Member

    Joined:
    Sep 7, 2010
    Messages:
    2,086
    Likes Received:
    64
    I guess I should have read the post entirely before "throwing" out a suggestion -

    I have SPA504s running on 7.5.5 as do you on the latest V12 sp3 release with no issue. I now see where DND had been covered (my apologies) and I also see where this seemingly affects all phones, which tends to rule out George's suggestion of a new phone. You also indicated in the initial post that outgoing calls are not a problem, so this too tends to rule out phones and firmware, but what about calls from extension to extension?

    Now then what I do not see is a description of the network to include the various IPs. You have them xxx'ed out which is good form, but these should be IPs from the private side as far as 3CX and the 504 go. I would prefer to see a log from 3CX rather than the one from the phone as I am concerned that we are seeing various logs. I would like to see the IPs to the extent possible. You might also want to run a wireshark and do a telephony flow under the SIP heading.

    The below appears to be an outbound call and these error codes seem to indicate that the endpoint is not reachable.

    08-Jan-2014 16:13:27.658 L:28.1[Extn] failed to reach Line:89999>>1723420300, reason Server Failure
    08-Jan-2014 16:13:27.658 Call to T:Line:89999>>1723420300@[Dev:sip:9999999999@xxxx:5060] from L:28.1[Extn] failed, cause: Cause: 503 Service Unavailable/INVITE from xxxxx:5060
    08-Jan-2014 16:13:27.658 [CM503003]: Call(C:28): Call to <sip:999999@xxxxx:5060> has failed; Cause: 503 Service Unavailable/INVITE from xxxxxx:5060

    The other aspects of the log seem to be an inbound call to ext 2045 wherein the busy here is given.

    Is it possible that the system has more than one NIC card?
     
  12. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    Internal calls also suffer from the busy/server failure issue.

    My original post was of the log entries from 3cx. Yes, you are correct in that the IP address are all private. I'll post updated log entries from 3cx in this post.

    It has only one enabled NIC and is configured with multiple private IP addresses, 3cx using one of those.

    Here are some updated action log entries from 3cx. I have left the private IP addresses in this time. Believe me when I tell you these are entries from inbound calls only.

    09-Jan-2014 16:47:33.998 Leg L:15.4[Extn] is terminated: Cause: 503 No matching transport found/INVITE from local
    09-Jan-2014 16:47:33.998 L:15.1[Line:89999<<xxxxxxxxxx] failed to reach Extn:2045, reason Server Failure
    09-Jan-2014 16:47:33.998 Call to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5060] from L:15.1[Line:89999<<xxxxxxxxxx] failed, cause: Cause: 503 No matching transport found/INVITE from local
    09-Jan-2014 16:47:33.998 Leg L:15.3[Extn] is terminated: Cause: 503 No matching transport found/INVITE from local
    09-Jan-2014 16:47:33.998 Call to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060] from L:15.1[Line:89999<<xxxxxxxxxx] failed, cause: Cause: 503 No matching transport found/INVITE from local
    09-Jan-2014 16:47:33.898 [CM503025]: Call(C:15): Calling T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060] for L:15.1[Line:89999<<xxxxxxxxxx]
    09-Jan-2014 16:47:33.896 [CM503025]: Call(C:15): Calling T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060] for L:15.1[Line:89999<<xxxxxxxxxx]
    09-Jan-2014 16:47:33.845 [CM503027]: Call(C:15): From: Line:89999<<xxxxxxxxxx (<sip:xxxxxxxxxx@xxx.xxx.49.254:5060>) to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060]
    09-Jan-2014 16:47:33.845 [CM503004]: Call(C:15): Route 1: from L:15.1[Line:89999<<xxxxxxxxxx] to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060]

    09-Jan-2014 16:48:14.320 Leg L:16.4[Extn] is terminated: Cause: 487 Request Terminated/INVITE from 192.168.1.71:5060
    09-Jan-2014 16:48:14.268 L:16.1[Line:89999<<xxxxxxxxxx] forwards call from Extn:2045 to VMail:6245 based on rule Fwd[Available/Busy]
    09-Jan-2014 16:48:14.268 L:16.1[Line:89999<<xxxxxxxxxx] failed to reach Extn:2045, reason Busy
    09-Jan-2014 16:48:14.268 Leg L:16.3[Extn] is terminated: Cause: 486 Busy Here/INVITE from 192.168.1.71:5061
    09-Jan-2014 16:48:14.267 Call to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060] from L:16.1[Line:89999<<xxxxxxxxxx] failed, cause: Cause: 486 Busy Here/INVITE from 192.168.1.71:5061
    09-Jan-2014 16:48:14.156 [CM503025]: Call(C:16): Calling T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060] for L:16.1[Line:89999<<xxxxxxxxxx]
    09-Jan-2014 16:48:14.154 [CM503025]: Call(C:16): Calling T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060] for L:16.1[Line:89999<<xxxxxxxxxx]
    09-Jan-2014 16:48:14.103 [CM503027]: Call(C:16): From: Line:89999<<xxxxxxxxxx (<sip:xxxxxxxxxx@xxx.xxx.49.254:5060>) to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060]
    09-Jan-2014 16:48:14.103 [CM503004]: Call(C:16): Route 1: from L:16.1[Line:89999<<xxxxxxxxxx] to T:Extn:2045@[Dev:sip:2045@192.168.1.71:5061,Dev:sip:2045@192.168.1.71:5060]
     
  13. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,073
    Likes Received:
    323
    What is the key configuration on the set given that the logs are showing two ports being used?

    Does extension 2045 reside on two line keys?
     
  14. lneblett

    lneblett Well-Known Member

    Joined:
    Sep 7, 2010
    Messages:
    2,086
    Likes Received:
    64
    agree with leejor as to why 5060/5061 from same ip being engaged. transport not found might be related to codec or to tls sip. might consider factory reset and the a manual provision to see.
     
  15. lneblett

    lneblett Well-Known Member

    Joined:
    Sep 7, 2010
    Messages:
    2,086
    Likes Received:
    64
    agree with leejor as to why 5060/5061 from same ip being engaged. transport not found might be related to codec or to tls sip. might consider factory reset and the a manual provision to see.
     
  16. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    To be honest I have no idea how it ended up that way. No, the extension should not have been on two keys.

    I took lneblett's advice and performed a factory reset on all phones and had 3cx reprovision each phone after applying minimal configuration. They are now all working as expected when the call actually does get transferred. Thank you for your help on this.

    I am still dealing with this however:

    10-Jan-2014 09:02:02.624 Leg L:33.2[Ivr] is terminated: Cause: BYE from PBX
    10-Jan-2014 09:02:02.624 [CM503008]: Call(C:33): Call is terminated
    10-Jan-2014 09:02:02.623 Leg L:33.1[Line:89999<<xxxxxxxxxx] is terminated: Cause: BYE from xxx.xxx.225.103:5060
    10-Jan-2014 09:01:59.170 [CM505003]: Provider:[Broadvox] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [3CXPhoneSystem 12.0.33517.465 (33463)] PBX contact: [sip:yyyyyyyyyy@xxx.xxx.49.254:5060]
    10-Jan-2014 09:01:59.170 Leg L:33.3[Extn] is terminated: Cause: 503 No matching transport found/INVITE from local
    10-Jan-2014 09:01:59.170 L:33.1[Line:89999<<xxxxxxxxxx] failed to reach Extn:2085, reason Server Failure
    10-Jan-2014 09:01:59.170 Call to T:Extn:2085@[Dev:sip:2085@192.168.1.33:5060] from L:33.1[Line:89999<<xxxxxxxxxx] failed, cause: Cause: 503 No matching transport found/INVITE from local
    10-Jan-2014 09:01:59.170 [CM503003]: Call(C:33): Call to <sip:2085@192.168.1.5:5060> has failed; Cause: 503 No matching transport found/INVITE from local
     
  17. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,073
    Likes Received:
    323
    The log would seem to indicate that there was no TCP or UDP transport to the end user. Check to be sure that the current options don't limit what transport method is to be used.
     
  18. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    Are you talking in terms of the firewall or a 3cx option?
     
  19. leejor

    leejor Well-Known Member

    Joined:
    Jan 22, 2008
    Messages:
    11,073
    Likes Received:
    323
    I was thinking more of a set option, but in your case, if there is a firewall in-between you might want to check that.
     
  20. Mike MSTG

    Joined:
    Jan 4, 2010
    Messages:
    13
    Likes Received:
    0
    I didn't think this to be a firewall issue since the call has been received by 3cx at this point; it just didn't route it to the phone. Seems like it's past the firewall at that point.

    SIP settings on each line on the set indicate UDP. Other than manually setting lines 2-4 to something other than UDP (TCP and TLS are the options given), I don't see an "auto" type of setting, or at least nothing that I recognize as being able to accept either UDP or TCP.

    Would the 3cx product switch between UDP and TCP arbitrarily? If it may then perhaps I need to update the provisioning template to set say line 3 and 4 to be the ones to accept a TCP SIP signal.

    That sound/seem right to you?
     
Thread Status:
Not open for further replies.