<SOLVED> SPA122 fast busy on outgoing calls

confluence3 · ‎12-29-2014

I have an SPA122 I'm having issues with running the 1.3.5 firmware. If I reset the device and configure only the items in the Simple Setup section, the phone will make and receive calls but there is a long delay between dialing the number and ringback starting. After some time (more than a few hours, not sure exactly when it occurs) the phone will stop being able to make outgoing calls. It will still generate a dial tone and allow me to dial the complete number but then after just a short pause I get a fast busy. I can reboot the device and nothing changes but if I reset it and then resupply the Simple Setup items it works again...for a while. The phone will still receive calls. I've registered the extension credentials to a softphone and it works with no problems. I've also brought the SPA122 to a different location (seperate ISP and network equipment) and have tried with a different phone and get the same results. Any suggestions would be greatly appreciated.

confluence3 · ‎12-30-2014

I thought it may be an issue with the dial plan but I've played around with it a bit without any success. I'm in North America so I'm using the dial plan (*xx|[3469]11|0|00|[2-9]xxxxxx|1xxx[2-9]xxxxxxS0|xxxxxxxxxxxx.). Anyone?

Dan Lukes · ‎12-31-2014

At the first, you need to identify why the call is rejected. It's either reason internal to device itself (Dial Plan, outgoing proxy unreachable, ...) or reason external to the device (call is rejected by upstream operator).

Turn on syslog&debug messages and catch them, as well as SIP communication between your device and upstream operator. It will help you to decide.

Further steps depends on the result of such analysis.

confluence3 · ‎04-01-2015

Dan,

Thanks for the reply and sorry for the delay. I've learned that each time it happens, rebooting the device does not help at all but doing a reset and then re-entering my credentials fixes it...for a week or so. Last couple times it happened I was in a hurry and just reset it.

It is now giving the fast busy on outgoing calls again. I've connected it to another network where other SIP devices are working with no change. I've enabled the syslog/debug but I'm not really sure what I'm looking at. Is there a guide somewhere that tells me what the different responses mean? I'm new to syslog so I don't know if this is something specific to SPA devices, Cisco devices, or all syslogs.

I have attached the portion that is generated when I attempt a call. If there is any help you can offer it is appreciated.

Apr 1 07:03:57 SPA122 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 20

Apr 1 07:03:57 SPA122 user.notice sprvoip: cmd - 5, response 8

Apr 1 07:03:57 SPA122 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 30

Apr 1 07:03:57 SPA122 user.notice sprvoip: cmd - 5, response 8

Apr 1 07:03:58 SPA122 user.notice sprvoip: cmd 2

Apr 1 07:03:58 SPA122 user.notice sprvoip: Seq Num 11

Apr 1 07:03:58 SPA122 user.notice sprvoip: cmd - 2, response 2

Apr 1 07:03:58 SPA122 user.notice sprvoip: cmd 10, EP 2, Node ID 0

Apr 1 07:03:58 SPA122 user.notice sprvoip: cmd - 10, response 10

Apr 1 07:03:58 SPA122 user.notice sprvoip: cmd 14, NodeId 0

Apr 1 07:03:58 SPA122 user.notice sprvoip: cmd - 14, response 18

Apr 1 07:04:00 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:00 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:01 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:01 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:01 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:01 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:01 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:01 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:02 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 14, response 43

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 14, response 42

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd 10, EP 3, Node ID 0

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 10, response 43

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 10, response 10

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd 5, EP 2, ParameterType 22, ParameterValue 1

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 5, response 8

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd 5, EP 2, ParameterType 27, ParameterValue 60

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 5, response 8

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd 5, EP 2, ParameterType 26, ParameterValue 70

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 5, response 8

Apr 1 07:04:03 SPA122 user.notice sprvoip: cmd - 23, response 38

Apr 1 07:04:04 SPA122 user.notice sprvoip: cmd - 20, response 34

Apr 1 07:04:04 SPA122 daemon.notice msgswitchd[231]: MSGSWD RTCP Reqt len 12 Data 2,0,52,195

Apr 1 07:04:04 SPA122 kern.warning [17179635.136000] voice_release, chan: 0

Apr 1 07:04:04 SPA122 user.notice sprvoip: cmd 11, EP 3

Apr 1 07:04:04 SPA122 user.notice sprvoip: cmd - 11, response 12

Apr 1 07:04:07 SPA122 user.notice sprvoip: cmd 16, NodeId 2

Apr 1 07:04:07 SPA122 user.notice sprvoip: cmd - 16, response 20

Apr 1 07:04:07 SPA122 user.notice sprvoip: cmd 14, NodeId 0

Apr 1 07:04:07 SPA122 user.notice sprvoip: cmd - 14, response 18

Apr 1 07:04:07 SPA122 user.notice sprvoip: cmd 12, NodeId 0

Apr 1 07:04:07 SPA122 user.notice sprvoip: cmd - 12, response 14

Dan Lukes · ‎04-01-2015

This is kernel log (Administration -> Log). It will not help us so much.

We need log of voice application (e.g. Voice->System). Set both server transport methods to UDP, debug level to 3 and {Syslog|Debug} Sever to IP of the server (one server can receive both type of messages).

It require external syslog server, but there are some free even for windows as far as I know.

This log should reveal something important to us. This kind of log may be more readable to you, despite they are not documented by Cisco. Well, it require a lot of experience and knowledge of protocols and procedures used to interpret them.

I can't promise they will solve the issue, but in most case they will help substantially.

On the other side, it the issue has returned to you with no configuration change and/or it appear and disappear at random, then it will be rather caused by something external to SPA122. In such case even the log may not help and capture of SIP packets may be necessary then.

confluence3 · ‎04-01-2015

Thanks again Dan for all the pointers. I've now learned how to setup a syslog server and how to capture and "somewhat" translate the data. In doing so, I was able to find and correct the problem. It was the stupid block caller ID * option. Someone apparently used it (I'm not the only phone user) and that stopped it from properly registering the outgoing calls. I switched the feature off and voila, it works. So, I've gone into the Regional settings now and removed the * code assignments (I don't use any of them) and all is well.

Dan Lukes · ‎04-01-2015

It's known truth that networks (both computer and phone) works better with no users at all. Unfortunately, bosses are not willing to understand such simple rule ;-)

And yes, CLIR supplemental service needs to be supported by upstream provider.

Glad to hear you found solution.