[asterisk-users] Asterisk not recognizing ACK from an OK message? Help debuging SIP retransmit problem

Fri Apr 23 20:52:47 CDT 2010

Hi all.

I am having lots of trouble with random calls dropping after 20
seconds, and I finally managed to capture a full sip trace. I'll paste
it in full below, but I'll give a summary first. It seems that
Asterisk is not recognizing the ACK messages that it receives from the
Grandstream ATA. This happens only on the ACK that follows the OK that
marks a call as established. This makes Asterisk retransmit the OK
message 6 times, after which it drops the call (after exactly 20
seconds).

The strange thing is that the "branch" parameter of the ACK is
different than the branch parameter from the OK it is replying to,
however, this seems to be normal behaviour as specified in the RFC for
an ACK that is sent in response to a 200 message.

I don't want to clutter the list, and the mail-bot marked as spam my previous
email with a pastie link, so I am only including the highlights of the
SIP dialog.
Any suggestions as to how to attach the whole thing (if necessary) are
appreciated.

>>> The call was ringing and is now answered:

<--- Reliably Transmitting (NAT) to 82.158.83.xxx:5062 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
82.158.83.xxx:5062;branch=z9hG4bK1226703311;received=82.158.83.xxx;rport=5062
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 82.158.83.xxx
CSeq: 31 INVITE
Server: VoIPSwitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: <sip:6615xxxxx at 130.117.xxx.xxx>
Content-Type: application/sdp
Content-Length: 235

v=0
o=root 1698171141 1698171142 IN IP4 130.117.xxx.xxx
s=Asterisk PBX 1.6.1.18
c=IN IP4 130.117.xxx.xxx
t=0 0
m=audio 39124 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
   -- Packet2Packet bridging SIP/800902-00001794 and
SIP/130.117.110.21-00001795

>>> ATA ACK's the OK message:

<--- SIP read from UDP://82.158.83.xxx:5062 --->
ACK sip:6615xxxxx at 130.117.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP 82.158.83.xxx:5062;branch=z9hG4bK1788524356;rport
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 192.168.1.100
CSeq: 31 ACK
Contact: <sip:800902 at 82.158.83.xxx:5062;user=phone>
Max-Forwards: 70
Supported: replaces, path, timer
User-Agent: Grandstream HT-502  V1.1C 1.0.1.57
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
Content-Length: 0

>>> Asterisk does not recognize and retransmits

<------------->
--- (12 headers 0 lines) ---
Retransmitting #1 (NAT) to 82.158.83.xxx:5062:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
82.158.83.xxx:5062;branch=z9hG4bK1226703311;received=82.158.83.xxx;rport=5062
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 82.158.83.xxx
CSeq: 31 INVITE
Server: VoIPSwitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: <sip:6615xxxxx at 130.117.xxx.xxx>
Content-Type: application/sdp
Content-Length: 235

v=0
o=root 1698171141 1698171142 IN IP4 130.117.xxx.xxx
s=Asterisk PBX 1.6.1.18
c=IN IP4 130.117.xxx.xxx
t=0 0
m=audio 39124 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

>>> ACK is received again

<--- SIP read from UDP://82.158.83.xxx:5062 --->
ACK sip:6615xxxxx at 130.117.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP 82.158.83.xxx:5062;branch=z9hG4bK1788524356;rport
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 192.168.1.100
CSeq: 31 ACK
Contact: <sip:800902 at 82.158.83.xxx:5062;user=phone>
Max-Forwards: 70
Supported: replaces, path, timer
User-Agent: Grandstream HT-502  V1.1C 1.0.1.57
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
Content-Length: 0

............... (cut)

>>> The retransmits happen 6 times and then:

<------------->
--- (12 headers 0 lines) ---
Retransmitting #6 (NAT) to 82.158.83.xxx:5062:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
82.158.83.xxx:5062;branch=z9hG4bK1226703311;received=82.158.83.xxx;rport=5062
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 82.158.83.xxx
CSeq: 31 INVITE
Server: VoIPSwitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Contact: <sip:6615xxxxx at 130.117.xxx.xxx>
Content-Type: application/sdp
Content-Length: 235

v=0
o=root 1698171141 1698171142 IN IP4 130.117.xxx.xxx
s=Asterisk PBX 1.6.1.18
c=IN IP4 130.117.xxx.xxx
t=0 0
m=audio 39124 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---

<--- SIP read from UDP://82.158.83.xxx:5062 --->
ACK sip:6615xxxxx at 130.117.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP 82.158.83.xxx:5062;branch=z9hG4bK1788524356;rport
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 192.168.1.100
CSeq: 31 ACK
Contact: <sip:800902 at 82.158.83.xxx:5062;user=phone>
Max-Forwards: 70
Supported: replaces, path, timer
User-Agent: Grandstream HT-502  V1.1C 1.0.1.57
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---

<--- SIP read from UDP://82.158.83.xxx:5062 --->

<------------->
[Apr 23 02:37:15] WARNING[3202]: chan_sip.c:3396 retrans_pkt: Maximum
retries exceeded on transmission 2117388659-5062-4 at 82.158.83.xxx for
seqno 31 (Critical Response) -- See doc/sip-retransmit.txt.
[Apr 23 02:37:15] WARNING[3202]: chan_sip.c:3423 retrans_pkt: Hanging
up call 2117388659-5062-4 at 82.158.83.xxx - no reply to our critical
packet (see doc/sip-retransmit.txt).
 == Spawn extension (default, 6615xxxxx, 27) exited non-zero on
'SIP/800902-00001794'
Really destroying SIP dialog '2117388659-5062-4 at 82.158.83.xxx' Method: INVITE

<--- SIP read from UDP://82.158.83.xxx:5062 --->
BYE sip:6615xxxxx at 130.117.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP 82.158.83.xxx:5062;branch=z9hG4bK1883566966;rport
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 192.168.1.100
CSeq: 32 BYE
Contact: <sip:800902 at 82.158.83.xxx:5062;user=phone>
Max-Forwards: 70
Supported: replaces, path, timer
User-Agent: Grandstream HT-502  V1.1C 1.0.1.57
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE
Content-Length: 0

<------------->
--- (12 headers 0 lines) ---

<--- Transmitting (no NAT) to 82.158.83.xxx:5062 --->
SIP/2.0 481 Call leg/transaction does not exist
Via: SIP/2.0/UDP
82.158.83.xxx:5062;branch=z9hG4bK1883566966;received=82.158.83.xxx;rport=5062
From: "800902" <sip:800902 at 130.117.xxx.xxx;user=phone>;tag=467506068
To: <sip:6615xxxxx at 130.117.xxx.xxx;user=phone>;tag=as2e12c791
Call-ID: 2117388659-5062-4 at 192.168.1.100
CSeq: 32 BYE
Server: VoIPSwitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
ontent-Length: 0

<------------>

Thank you for your help!

Alex