Cisco SPA504g always busy or not available

[Mike MSTG]

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?

 

[leejor]

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.

 

[Mike MSTG]

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.

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.

 

[leejor]

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.

 

[Mike MSTG]

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.

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

 

[Mike MSTG]

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.

 

[Mike MSTG]

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:[email protected]>;tag=47b68e3a827087bbi0
From: <sip:[email protected]: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:[email protected]:5060>
Server: Cisco/SPA504G-7.5.5
Content-Length: 0


[0]<<xxx.xxx.1.2:5060
CANCEL sip:[email protected]: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:[email protected]>
From: <sip:[email protected]: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:[email protected]>;tag=47b68e3a827087bbi0
From: <sip:[email protected]: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:[email protected]>;tag=47b68e3a827087bbi0
From: <sip:[email protected]: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:[email protected]: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:[email protected]>;tag=47b68e3a827087bbi0
From: <sip:[email protected]: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)

 

[lneblett]

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.

 

[Mike MSTG]

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.

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

 

[gschwab]

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.

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

My next step would be to try another phone

 

[lneblett]

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?

 

[Mike MSTG]

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?

Internal calls also suffer from the busy/server failure issue.

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.

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.

Is it possible that the system has more than one NIC card?

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:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]:5060] for L:15.1[Line:89999<<xxxxxxxxxx]
09-Jan-2014 16:47:33.845 [CM503027]: Call(C:15): From: Line:89999<<xxxxxxxxxx (<sip:[email protected]:5060>) to T:Extn:2045@[Dev:sip:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]:5060] for L:16.1[Line:89999<<xxxxxxxxxx]
09-Jan-2014 16:48:14.103 [CM503027]: Call(C:16): From: Line:89999<<xxxxxxxxxx (<sip:[email protected]:5060>) to T:Extn:2045@[Dev:sip:[email protected]:5061,Dev:sip:[email protected]: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:[email protected]:5061,Dev:sip:[email protected]:5060]

 

[leejor]

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?

 

[lneblett]

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.

 

[lneblett]

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.

 

[Mike MSTG]

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?

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:[email protected]: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:[email protected]: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:[email protected]:5060> has failed; Cause: 503 No matching transport found/INVITE from local

 

[leejor]

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.

 

[Mike MSTG]

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.

Are you talking in terms of the firewall or a 3cx option?

 

[leejor]

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.

 

[Mike MSTG]

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?