[asterisk-users] No response to our critical packet problem

Fri May 22 12:36:59 CDT 2009

Hi,
I have a strange problem. At a site where there are 20+ phones, there
is one phone that cannot make outbound (to PSTN) calls.
Each call is dropped after 20s with "no response to our critical packet".
Calls to voicemail and internal extensions work fine.

I understand that everything points to a NAT problem, but I don't
understand how it could be because:
1) It does not affect calls to internal office extensions (which still
go through asterisk) OR voicemail
2) The other 20+ phones in the same office on the same network have 0 problems.

Here's a SIP trace of the problem.
yyy.yyy.yyy.yyy is the outside NAT IP
xxx.xxx.xxx.xxx is the IP of my PBX
dddddddddd is the dialed phone number
sssssssssss is the source phone number

The peculiar thing is that asterisk sends an OK in response to an INVITE,
then the phone sends back an ACK, which asterisk seems to ignore
because it retransmits the OK message again
Then eventually the phone gives up and sends a BYE message.

-- James

<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
INVITE sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-6e730c81^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 101 INVITE^M
Max-Forwards: 70^M
Contact: "sss-sss-ssss" ^M
Expires: 240^M
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 395^M
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER^M
Supported: replaces^M
Content-Type: application/sdp^M
^M
v=0^M
o=- 6363534 6363534 IN IP4 10.1.24.145^M
s=-^M
c=IN IP4 10.1.24.145^M
t=0 0^M
m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:2 G726-32/8000^M
a=rtpmap:4 G723/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:18 G729a/8000^M
a=rtpmap:96 G726-40/8000^M
a=rtpmap:97 G726-24/8000^M
a=rtpmap:98 G726-16/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-15^M
a=ptime:20^M
a=sendrecv^M
<------------->
<--- Reliably Transmitting (NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 407 Proxy Authentication Required^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-6e730c81;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as70a8455c^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 101 INVITE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="6d2db4b7"^M
Content-Length: 0^M
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
ACK sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-6e730c81^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as70a8455c^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 101 ACK^M
Max-Forwards: 70^M
Contact: "sss-sss-ssss" ^M
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 0^G
^M
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
INVITE sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-3d87585d^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 INVITE^M
Max-Forwards: 70^M
Proxy-Authorization: Digest
username="ssssssssss",realm="asterisk",nonce="6d2db4b7",uri="sip:dddddddddd at xxx.xxx.xxx.xxx",algorithm=MD5,response=
Contact: "sss-sss-ssss" ^M
Expires: 240^M
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 395^M
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER^M
Supported: replaces^M
Content-Type: application/sdp^M
^M
v=0^M
o=- 6363534 6363534 IN IP4 10.1.24.145^M
s=-^M
c=IN IP4 10.1.24.145^M
t=0 0^M
m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:2 G726-32/8000^M
a=rtpmap:4 G723/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:18 G729a/8000^M
a=rtpmap:96 G726-40/8000^M
a=rtpmap:97 G726-24/8000^M
a=rtpmap:98 G726-16/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-15^M
a=ptime:20^M
a=sendrecv^M
<------------->
<--- Transmitting (NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 100 Trying^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-3d87585d;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 INVITE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Contact: ^M
Content-Length: 0^M
^M
<------------>
<--- Transmitting (NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 183 Session Progress^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-3d87585d;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 INVITE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Contact: ^M
Content-Type: application/sdp^M
Content-Length: 264^M
^M
v=0^M
o=root 32147 32147 IN IP4 xxx.xxx.xxx.xxx^M
s=session^M
c=IN IP4 xxx.xxx.xxx.xxx^M
t=0 0^M
m=audio 19536 RTP/AVP 0 8 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=silenceSupp:off - - - -^M
a=ptime:20^M
a=sendrecv^M
<------------>
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
INFO sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-234dc2a4^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 103 INFO^M
Max-Forwards: 70^M
Proxy-Authorization: Digest
username="ssssssssss",realm="asterisk",nonce="6d2db4b7",uri="sip:dddddddddd at xxx.xxx.xxx.xxx",algorithm=MD5,response=
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 24^M
Content-Type: application/dtmf-relay^M
^M
Signal=#^M
Duration=100^M
<------------->
<--- Transmitting (NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-234dc2a4;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 103 INFO^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Contact: ^M
Content-Length: 0^M
^M
<------------>
<--- Transmitting (NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 180 Ringing^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-3d87585d;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 INVITE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Contact: ^M
Content-Length: 0^M
^M
<------------>
OPTIONS sip:ssssssssss at 10.1.24.145:7388 SIP/2.0^M
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK481375ee;rport^M
From: "Unknown" ;tag=as1e5e0912^M
To: ^M
Contact: ^M
Call-ID: 47649b454714f359238cb6bb41eb75dd at xxx.xxx.xxx.xxx^M
CSeq: 102 OPTIONS^M
User-Agent: Asterisk PBX^M
Max-Forwards: 70^M
Date: Fri, 22 May 2009 16:49:47 GMT^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Content-Length: 0^M
^M
---
[May 22 09:49:47] VERBOSE[32177] logger.c:
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 200 OK^M
To: ;tag=6bb2ad0e65f932fi0^M
From: "Unknown" ;tag=as1e5e0912^M
Call-ID: 47649b454714f359238cb6bb41eb75dd at xxx.xxx.xxx.xxx^M
CSeq: 102 OPTIONS^M
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx:5060;branch=z9hG4bK481375ee^M
Server: Linksys/SPA942-6.1.3(a)^M
Content-Length: 0^M
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER^M
Supported: replaces^M
^M
<------------->
<--- Reliably Transmitting (NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-3d87585d;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 INVITE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Contact: ^M
Content-Type: application/sdp^M
Content-Length: 264^M
^M
v=0^M
o=root 32147 32148 IN IP4 xxx.xxx.xxx.xxx^M
s=session^M
c=IN IP4 xxx.xxx.xxx.xxx^M
t=0 0^M
m=audio 19536 RTP/AVP 0 8 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=silenceSupp:off - - - -^M
a=ptime:20^M
a=sendrecv^M
<------------>
[May 22 09:49:52] VERBOSE[32177] logger.c:
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
ACK sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-21970f9d^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 ACK^M
Max-Forwards: 70^M
Proxy-Authorization: Digest
username="ssssssssss",realm="asterisk",nonce="6d2db4b7",uri="sip:dddddddddd at xxx.xxx.xxx.xxx",algorithm=MD5,response=
Contact: "sss-sss-ssss" ^M
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 0^M
^M
<------------->
Retransmitting #1 (NAT) to yyy.yyy.yyy.yyy:24050:
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-3d87585d;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 INVITE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Contact: ^M
Content-Type: application/sdp^M
Content-Length: 264^M
^M
v=0^M
o=root 32147 32148 IN IP4 xxx.xxx.xxx.xxx^M
s=session^M
c=IN IP4 xxx.xxx.xxx.xxx^M
t=0 0^M
m=audio 19536 RTP/AVP 0 8 101^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=silenceSupp:off - - - -^M
a=ptime:20^M
a=sendrecv^M
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
ACK sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-21970f9d^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 102 ACK^M
Max-Forwards: 70^M
Proxy-Authorization: Digest
username="ssssssssss",realm="asterisk",nonce="6d2db4b7",uri="sip:dddddddddd at xxx.xxx.xxx.xxx",algorithm=MD5,response=
Contact: "sss-sss-ssss" ^M
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 0^M
^M
[ RETRANSMIT ABOVE 6 TIMES ]
<--- SIP read from yyy.yyy.yyy.yyy:24050 --->
BYE sip:dddddddddd at xxx.xxx.xxx.xxx SIP/2.0^M
Via: SIP/2.0/UDP 10.1.24.145:7388;branch=z9hG4bK-18e57808^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 104 BYE^M
Max-Forwards: 70^M
Proxy-Authorization: Digest
username="ssssssssss",realm="asterisk",nonce="6d2db4b7",uri="sip:dddddddddd at xxx.xxx.xxx.xxx",algorithm=MD5,response="5090
User-Agent: Linksys/SPA942-6.1.3(a)^M
Content-Length: 0^M
^M
<------------->
<--- Transmitting (no NAT) to yyy.yyy.yyy.yyy:24050 --->
SIP/2.0 481 Call leg/transaction does not exist^M
Via: SIP/2.0/UDP
10.1.24.145:7388;branch=z9hG4bK-18e57808;received=yyy.yyy.yyy.yyy^M
From: "sss-sss-ssss" ;tag=bdfe4214c494d109o0^M
To: ;tag=as30846812^M
Call-ID: c4560330-de7ca29d at 10.1.24.145^M
CSeq: 104 BYE^M
User-Agent: Asterisk PBX^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Content-Length: 0^M
^M
<------------>