SPA9000 Won't receive inbound SIP calls

madisontmajor · ‎08-03-2011

Hi Guys,

We have a client with an SPA900, SPA400 and 4x SPA942s. They signed up for a new SIP service through Nexvortex. All outbound calls work great, but an inbound call to either of their DIDs fails. The DIDs have been provisioned and I can see calls hitting SYSLOG. The error I receive is as follows:

08-03-2011 16:00:00 Local0.Info 192.168.1.4

08-03-2011 16:00:00 Local0.Info 192.168.1.4 [2]<<66.23.129.253:5060(445)

08-03-2011 16:00:00 Local0.Info 192.168.1.4

08-03-2011 16:00:00 Local0.Info 192.168.1.4 [2]->66.23.129.253:5060(692)

08-03-2011 16:00:00 Local0.Info 192.168.1.4 pri--REJECT Call(reason=39)-->pub

08-03-2011 15:59:58 Local2.Debug 192.168.1.52 [0]RegOK. NextReg in 29 (1)

08-03-2011 15:59:51 Local0.Info 192.168.1.4

08-03-2011 15:59:51 Local0.Info 192.168.1.4 [2]->66.23.129.253:5060(611)

Currently, we have a contact rule setup to send each DID to a specific extension. If I remove the Contact List Rule, the phones still will not ring when an inbound call is received.

Any ideas?

Thanks

Madison

madisontmajor · ‎08-04-2011

This is what I am seeing from syslog when I place a call to the SPA 9000. For reference 192.168.1.4 is the PBX (SPA 9000). Any help here would be much appreciated.

Record-Route: <sip:17736445362@66.23.129.253:5060;nat=yes;ftag=a9d5ed0-13c4-4e3adfe5-6fb53347-577f1e44;lr=on>

From: <17084660658>;tag=a9d5ed0-13c4-4e3adfe5-6fb53347-577f1e44

To: <17736445362>

Call-ID: CXC-36-6b334650-a9d5ed0-13c4-4e3adfe5-6fb53347-683fd4d6@208.94.157.10

CSeq: 1 INVITE

Via: SIP/2.0/UDP 66.23.129.253:5060;branch=z9hG4bKa2ff.1bccbaa.0

Via: SIP/2.0/UDP 208.94.157.10:5060;branch=z9hG4bK-8e4a9-4e3adfe5-6fb53347-28f0cb2d

Max-Forwards: 16

P-Asserted-Identity: <>17084660658@cxc.dashcs.com:5060>

Content-Disposition: session;handling=required

Contact: <17084660658>

Min-SE: 900

Session-Expires: 1800

Content-Type: application/sdp

Content-Length: 238

v=0

o=Acme_UAS 0 1 IN IP4 208.94.157.10

s=SIP Media Capabilities

c=IN IP4 208.94.157.10

t=0 0

m=audio 20062 RTP/AVP 0 18 101

a=rtpmap:0 PCMU/8000

...

2011-08-04 13:07:30 Local0.Info 192.168.1.4

2011-08-04 13:07:30 Local0.Info 192.168.1.4 [2]->66.23.129.253:5060(621)

2011-08-04 13:07:30 Local7.Debug 192.168.1.4 SIP/2.0 100 Trying

To: <sip:17736445362@66.23.129.253:5060>

From: <17084660658>;tag=a9d5ed0-13c4-4e3adfe5-6fb53347-577f1e44

Call-ID: CXC-36-6b334650-a9d5ed0-13c4-4e3adfe5-6fb53347-683fd4d6@208.94.157.10

CSeq: 1 INVITE

Via: SIP/2.0/UDP 66.23.129.253:5060;branch=z9hG4bKa2ff.1bccbaa.0

Via: SIP/2.0/UDP 208.94.157.10:5060;branch=z9hG4bK-8e4a9-4e3adfe5-6fb53347-28f0cb2d

Record-Route: <17736445362>

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference, x-spa-cti

Content-Length: 0

2011-08-04 13:07:30 Local0.Info 192.168.1.4

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [5060]STUN trying 0

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16402]STUN trying 0

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16403]STUN trying 0

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16404]STUN trying 0

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16405]STUN trying 0

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [5060]STUN trying 1

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16402]STUN trying 1

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16403]STUN trying 1

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16404]STUN trying 1

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16405]STUN trying 1

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [5060]STUN trying 2

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16402]STUN trying 2

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16403]STUN trying 2

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16404]STUN trying 2

2011-08-04 13:07:30 Local2.Debug 192.168.1.4 [16405]STUN trying 2

2011-08-04 13:07:31 Local2.Debug 192.168.1.4 [5060]STUN trying 3

2011-08-04 13:07:31 Local2.Debug 192.168.1.4 [16402]STUN trying 3

2011-08-04 13:07:31 Local2.Debug 192.168.1.4 [16403]STUN trying 3

2011-08-04 13:07:31 Local2.Debug 192.168.1.4 [16404]STUN trying 3

2011-08-04 13:07:31 Local2.Debug 192.168.1.4 [16405]STUN trying 3

2011-08-04 13:07:32 Local2.Debug 192.168.1.4 [5060]STUN trying 4

2011-08-04 13:07:32 Local2.Debug 192.168.1.4 [16402]STUN trying 4

2011-08-04 13:07:32 Local2.Debug 192.168.1.4 [16403]STUN trying 4

2011-08-04 13:07:32 Local2.Debug 192.168.1.4 [16404]STUN trying 4

2011-08-04 13:07:32 Local2.Debug 192.168.1.4 [16405]STUN trying 4

2011-08-04 13:07:33 Local2.Debug 192.168.1.4 [5060]STUN trying 5

2011-08-04 13:07:33 Local2.Debug 192.168.1.4 [16402]STUN trying 5

2011-08-04 13:07:33 Local2.Debug 192.168.1.4 [16403]STUN trying 5

2011-08-04 13:07:33 Local2.Debug 192.168.1.4 [16404]STUN trying 5

2011-08-04 13:07:33 Local2.Debug 192.168.1.4 [16405]STUN trying 5

2011-08-04 13:07:34 Local2.Debug 192.168.1.56 [0]RegOK. NextReg in 29 (1)

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [5060]STUN trying 6

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16402]STUN trying 6

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16403]STUN trying 6

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16404]STUN trying 6

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16405]STUN trying 6

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [5060]STUN trying 7

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16402]STUN trying 7

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16403]STUN trying 7

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16404]STUN trying 7

2011-08-04 13:07:36 Local2.Debug 192.168.1.4 [16405]STUN trying 7

2011-08-04 13:07:38 Local2.Debug 192.168.1.4 [5060]STUN trying 8

2011-08-04 13:07:38 Local2.Debug 192.168.1.4 [16402]STUN trying 8

2011-08-04 13:07:38 Local2.Debug 192.168.1.4 [16403]STUN trying 8

2011-08-04 13:07:38 Local2.Debug 192.168.1.4 [16404]STUN trying 8

2011-08-04 13:07:38 Local2.Debug 192.168.1.4 [16405]STUN trying 8

2011-08-04 13:07:40 Local2.Debug 192.168.1.4 [2:0]STUN Failed

2011-08-04 13:07:40 Local0.Info 192.168.1.4 [pxy]->192.168.1.55:5060(644)

2011-08-04 13:07:40 Local7.Debug 192.168.1.4 INVITE sip:102@192.168.1.55:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.1.4:6060;branch=z9hG4bK-b05c6c34;rport

From: <17084660658>;tag=7268b01854cde66bo2

To: <102>

Call-ID: e2332f5c-b181cff7@192.168.1.4

CSeq: 101 INVITE

Max-Forwards: 70

Contact: "" <17084660658>

Expires: 240

User-Agent: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference, x-spa-cti

Content-Length: 67

Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER

Supported: x-sipura, replaces

Content-Type: application/sdp

v=0

o=- IN IP4 173.161.44.5

s=-

c=IN IP4 173.161.44.5

t=0 0

2011-08-04 13:07:40 Local0.Info 192.168.1.4

2011-08-04 13:07:40 Local0.Info 192.168.1.4 [pxy]<<192.168.1.55:5060(292)

2011-08-04 13:07:40 Local7.Debug 192.168.1.4 SIP/2.0 100 Trying

To: <sip:102@192.168.1.4>

From: <17084660658>;tag=7268b01854cde66bo2

Call-ID: e2332f5c-b181cff7@192.168.1.4

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.1.4:6060;branch=z9hG4bK-b05c6c34

Server: Linksys/SPA942-6.1.5(a)

Content-Length: 0

2011-08-04 13:07:40 Local0.Info 192.168.1.4

2011-08-04 13:07:40 Local0.Info 192.168.1.4 [pxy]<<192.168.1.55:5060(373)

2011-08-04 13:07:40 Local7.Debug 192.168.1.4 SIP/2.0 488 Not Acceptable Here

To: <sip:102@192.168.1.4>;tag=d2d4205569b90bd9i0

From: <17084660658>;tag=7268b01854cde66bo2

Call-ID: e2332f5c-b181cff7@192.168.1.4

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.1.4:6060;branch=z9hG4bK-b05c6c34

Warning: 304 spa "Media type not available"

Server: Linksys/SPA942-6.1.5(a)

Content-Length: 0

2011-08-04 13:07:40 Local0.Info 192.168.1.4

2011-08-04 13:07:40 Local0.Info 192.168.1.4 [pxy]->192.168.1.55:5060(454)

2011-08-04 13:07:40 Local7.Debug 192.168.1.4 ACK sip:102@192.168.1.55:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.1.4:6060;branch=z9hG4bK-b05c6c34;rport

From: <17084660658>;tag=7268b01854cde66bo2

To: <102>;tag=d2d4205569b90bd9i0

Call-ID: e2332f5c-b181cff7@192.168.1.4

CSeq: 101 ACK

Max-Forwards: 70

Contact: "" <17084660658>

User-Agent: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference, x-spa-cti

Content-Length: 0

2011-08-04 13:07:40 Local0.Info 192.168.1.4

2011-08-04 13:07:40 Local0.Info 192.168.1.4 pri--REJECT Call(reason=39)-->pub

2011-08-04 13:07:40 Local0.Info 192.168.1.4 [2]->66.23.129.253:5060(702)

2011-08-04 13:07:40 Local7.Debug 192.168.1.4 SIP/2.0 488 Not Acceptable Here

To: <sip:17736445362@66.23.129.253:5060>;tag=e1d1f9009ab6f2a4i2

From: <17084660658>;tag=a9d5ed0-13c4-4e3adfe5-6fb53347-577f1e44

Call-ID: CXC-36-6b334650-a9d5ed0-13c4-4e3adfe5-6fb53347-683fd4d6@208.94.157.10

CSeq: 1 INVITE

Via: SIP/2.0/UDP 66.23.129.253:5060;branch=z9hG4bKa2ff.1bccbaa.0

Via: SIP/2.0/UDP 208.94.157.10:5060;branch=z9hG4bK-8e4a9-4e3adfe5-6fb53347-28f0cb2d

Record-Route: <17736445362>

Warning: 304 spa "Media type not available"

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference, x-spa-cti

Content-Length: 006

2011-08-04 13:07:40 Local0.Info 192.168.1.4

2011-08-04 13:07:40 Local0.Info 192.168.1.4 [2]<<66.23.129.253:5060(455)

2011-08-04 13:07:40 Local7.Debug 192.168.1.4 ACK sip:17736445362@173.161.44.5;transport=udp SIP/2.0

Via: SIP/2.0/UDP 66.23.129.253:5060;branch=z9hG4bKa2ff.1bccbaa.0

From: <17084660658>;tag=a9d5ed0-13c4-4e3adfe5-6fb53347-577f1e44

Call-ID: CXC-36-6b334650-a9d5ed0-13c4-4e3adfe5-6fb53347-683fd4d6@208.94.157.10

To: <17736445362>;tag=e1d1f9009ab6f2a4i2

CSeq: 1 ACK

User-Agent: Sip EXpress router(0.9.6 (x86_64/linux))

Content-Length: 0

2011-08-04 13:07:40 Local0.Info 192.168.1.4

2011-08-04 13:07:40 Local2.Debug 192.168.1.4 DLG Terminated 3a43f8

2011-08-04 13:07:40 Local2.Debug 192.168.1.4 Sess Terminated 3c1bb4

2011-08-04 13:07:50 Local3.Debug 192.168.1.4 [3]RegOK. NextReg in 28 (1)

2011-08-04 13:07:50 Local0.Info 192.168.1.4 +++ full fxo report

2011-08-04 13:07:50 Local0.Info 192.168.1.4 +++[3]fxo port mask = 0

2011-08-04 13:07:50 Local2.Debug 192.168.1.4 [3]SubOK. NextSub in 29 (1)

2011-08-04 13:07:54 Local0.Info 192.168.1.4 [2]->66.23.129.253:5060(484)

2011-08-04 13:07:54 Local7.Debug 192.168.1.4 SUBSCRIBE sip:8888@192.168.15.18:5090 SIP/2.0

Via: SIP/2.0/UDP 173.161.44.5:5060;branch=z9hG4bK-1786c7de;rport

From: "" ;tag=8431bff624dedf8

To: ""

Call-ID: 8d91ce4e-2db97380@192.168.1.4

CSeq: 59623 SUBSCRIBE

Max-Forwards: 70

Contact: ""

Expires: 30

Event: message-summary

User-Agent: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference, x-spa-cti

Content-Length: 0

2011-08-04 13:07:54 Local0.Info 192.168.1.4

2011-08-04 13:07:54 Local0.Info 192.168.1.4 [2]<<66.23.129.253:5060(383)

2011-08-04 13:07:54 Local7.Debug 192.168.1.4 SIP/2.0 500 I'm terribly sorry, server error occurred (1/SL)

Via: SIP/2.0/UDP 173.161.44.5:5060;branch=z9hG4bK-1786c7de;rport=5060

From: "" ;tag=8431bff624dedf8

To: "" ;tag=9c6a9fdfd4d16ebaa52f34c4c528cbe5.a691

Call-ID: 8d91ce4e-2db97380@192.168.1.4

CSeq: 59623 SUBSCRIBE

Server: nVSIP 12.02.01

Content-Length: 0

2011-08-04 13:07:54 Local0.Info 192.168.1.4

2011-08-04 13:07:54 Local2.Debug 192.168.1.4 [2]SUBS:Failed(43). Retry in 30s

madisontmajor · ‎08-04-2011

Now it appears that roughly 1/20 calls are being received.

madisontmajor · ‎08-05-2011

Does anyone know what the message

pri--REJECT Call(reason=39)-->pub

means?

madisontmajor · ‎08-05-2011

I asked my carrier to do a trace and they said my system is rejecting incoming calls with a "484 rejection"

Any help would be much appreciated.

madisontmajor · ‎08-12-2011

The solution ended up being an issue with the SPA9000 and it's communication with the Nexvortex stun server. I switched to the 3cx stun server and everything started working fine.