[Home]

Summary:ASTERISK-14741: [patch] chan_sip will not retransmit an ACK
Reporter:Nikos Mavrogianopoulos (nmav)Labels:
Date Opened:2009-08-31 10:10:05Date Closed:2011-07-26 14:24:01
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) ack.log
( 1) activate-retransmissions.patch
( 2) debug.txt
Description:In commit 204243 it was added a check on whether to retransmit an ACK or not. In my case this breaks retransmission in the following scenario:
-> INVITE
<- 100 Trying
<- 180 Ringing
<- 200 OK SDP
[ACK is lost]
<- 200 OK SDP
<- 200 OK SDP

Comments:By: Nikos Mavrogianopoulos (nmav) 2009-09-01 06:39:43

This scenario was between two asterisk acting as SIP clients and ser acting as server.
By: Olle Johansson (oej) 2009-09-03 09:51:06

As with all issues reported in the SIP category, we need a full output of SIP debug, with verbosity 4 and debug 4 in your asterisk. It's mentioned in the bug guidelines and will help us quite a bit to understand what's going on in your Asterisk. Thanks.
By: Nikos Mavrogianopoulos (nmav) 2009-09-03 10:05:46

Here is a capture of a conversation that terminates...

Reliably Transmitting (NAT) to 192.168.240.34:5060:
INVITE sip:2104500001@192.168.240.34 SIP/2.0
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>
Contact: <sip:nmav1@172.16.1.105>
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Max-Forwards: 70
Date: Thu, 03 Sep 2009 15:02:18 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1920 1920 IN IP4 172.16.1.105
s=-
c=IN IP4 172.16.1.105
t=0 0
m=audio 15182 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv

---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
Server: Sip EXpress router (0.9.6 (i386/linux))
Content-Length: 0
Warning: 392 192.168.240.34:5060 "Noisy feedback tells: pid=22332 req_src_ip=172.16.1.105 req_src_port=5060 in_uri=sip:2104500001@192.168.240.34 out_uri=sip:2104500001@172.16.1.117 via_cnt==1"

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

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Length: 0

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

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->
--- (13 headers 12 lines) ---

Found RTP audio format 18
Found RTP audio format 101
Peer audio RTP is at port 172.16.1.117:15362
Found audio description format G729 for ID 18
Found audio description format telephone-event for ID 101
Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - (g729)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
Peer audio RTP is at port 172.16.1.117:15362
list_route: hop: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
set_destination: Parsing <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on> for address/port to send to
set_destination: set destination to 192.168.240.34, port 5060
Transmitting (NAT) to 192.168.240.34:5060:
ACK sip:2104500001@172.16.1.117 SIP/2.0
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK053d8313;rport
Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Contact: <sip:nmav1@172.16.1.105>
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 ACK
User-Agent: Gennet Oxygen
Max-Forwards: 70
Content-Length: 0


---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->
--- (13 headers 12 lines) ---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->

--- (13 headers 12 lines) ---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->
--- (13 headers 12 lines) ---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->
--- (13 headers 12 lines) ---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->
--- (13 headers 12 lines) ---

oxygen*CLI>
<--- SIP read from 192.168.240.34:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.1.105:5060;branch=z9hG4bK68e6563f;rport=5060
Record-Route: <sip:192.168.240.34;ftag=as1f6eb1bc;lr=on>
From: "2104000001" <sip:nmav1@192.168.240.34>;tag=as1f6eb1bc
To: <sip:2104500001@192.168.240.34>;tag=as65e71d5d
Call-ID: 2ce79cb63488e59d5acedcf424f18dbd@192.168.240.34
CSeq: 102 INVITE
User-Agent: Gennet Oxygen
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: <sip:2104500001@172.16.1.117>
Content-Type: application/sdp
Content-Length: 234

v=0
o=root 1468 1468 IN IP4 172.16.1.117
s=-
c=IN IP4 172.16.1.117
t=0 0
m=audio 15362 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:40
a=sendrecv
<------------->
--- (13 headers 12 lines) ---

[here the peer - asterisk also - hangs the line up]
By: Olle Johansson (oej) 2009-09-07 01:04:09

Thank you.

Please add debug output as an attached file next time. :-)

There's something wrong with the output - there's no debug messages from chan_sip in there. Can you please try again and make sure you get those? THanks.
By: astman (astman) 2009-09-07 01:21:44

<--- SIP read from 10.32.128.100:28108 --->
ACK sip:*97@10.34.36.246:5060 SIP/2.0
Via: SIP/2.0/UDP 10.32.128.100:28108;branch=z9hG4bK-d8754z-fb1a1276c30a201e-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:4009@10.32.128.100:28108>
To: "*97"<sip:*97@10.34.36.246:5060>;tag=as0cc07d6d
From: "4009"<sip:4009@10.34.36.246:5060>;tag=bd7e0630
Call-ID: YjYxMmU3MDkyZWM0OWU1NWE4YmM3Yjk2OTljNzU3NWQ.
CSeq: 2 ACK
Proxy-Authorization: Digest username="4009",realm="asterisk",nonce="177c988f",uri="sip:*97@10.34.36.246",response="a6a7e9ea319751c00bc167925f56f4d0",algorithm=MD5
User-Agent: X-Lite release 1103k stamp 53621
Content-Length: 0


<------------->
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 0: ACK sip:*97@10.34.36.246:5060 SIP/2.0 (37)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 1: Via: SIP/2.0/UDP 10.32.128.100:28108;branch=z9hG4bK-d8754z-fb1a1276c30a201e-1---d8754z-;rport (93)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 2: Max-Forwards: 70 (16)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 3: Contact: <sip:4009@10.32.128.100:28108> (39)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 4: To: "*97"<sip:*97@10.34.36.246:5060>;tag=as0cc07d6d (51)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 5: From: "4009"<sip:4009@10.34.36.246:5060>;tag=bd7e0630 (53)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 6: Call-ID: YjYxMmU3MDkyZWM0OWU1NWE4YmM3Yjk2OTljNzU3NWQ. (53)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 7: CSeq: 2 ACK (11)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 8: Proxy-Authorization: Digest username="4009",realm="asterisk",nonce="177c988f",uri="sip:*97@10.34.36.246",response="a6a7e9ea319751c00bc167925f56f4d0",algorithm=MD5 (162)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 9: User-Agent: X-Lite release 1103k stamp 53621 (44)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 10: Content-Length: 0 (17)
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4981 parse_request: Header 11:  (0)
--- (11 headers 0 lines) ---
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:4751 find_call: = Found Their Call ID: YjYxMmU3MDkyZWM0OWU1NWE4YmM3Yjk2OTljNzU3NWQ. Their Tag bd7e0630 Our tag: as0cc07d6d
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:15422 handle_request: **** Received ACK (6) - Command in SIP ACK
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:2280 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid DAHLIN-183
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:2290 __sip_ack: Stopping retransmission on 'YjYxMmU3MDkyZWM0OWU1NWE4YmM3Yjk2OTljNzU3NWQ.' of Response 2: Match Not Found
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:2067 retrans_pkt: SIP TIMER: Rescheduling retransmission ASTERISK-15885 (1) SIP/2.0 - 1
[Sep  7 05:31:22] DEBUG[31476]: chan_sip.c:2081 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id ASTERISK-15885))
Retransmitting #1 (NAT) to 10.32.128.100:28108:
SIP/2.0 200 OK
=======================================
static void __sip_ack(struct sip_pvt *p, int seqno, int resp, int sipmethod)
{                   ...
UNLINK(cur, p->packets, prev);
if (cur->retransid > -1) {
if (sipdebug && option_debug > 3)
ast_log(LOG_DEBUG, "** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #%d\n", cur->retransid);
ast_sched_del(sched,cur->retransid);//HERE,seems no effect
cur->retransid = -1;
}
...
}
}
ast_mutex_unlock(&p->lock);
if (option_debug)
ast_log(LOG_DEBUG, "Stopping retransmission on '%s' of %s %d: Match %s\n", p->callid, resp ? "Response" : "Request", seqno, res ? "Not Found" : "Found");// ???
}
=================
hope this will help you,Thanks


By: Olle Johansson (oej) 2009-09-07 01:25:19

astman: If you want to add code to the issue tracker, you need to upload it as an attached file (because of Digium licensing restrictions). If you have changed something, we like to see a "diff" output so it's easy to understand what you've changed. Thanks.
By: Nikos Mavrogianopoulos (nmav) 2009-09-07 02:08:36

Hi, I attach the output of verbose 10 and debug 10 in the debug.txt file.
By: Olle Johansson (oej) 2009-09-07 02:28:03

Nmav: thank you. What is your sip.conf settings for this device in regards to NAT?
By: Nikos Mavrogianopoulos (nmav) 2009-09-07 02:47:06

I have: nat=yes
By: Olle Johansson (oej) 2009-09-10 14:14:18

I need to see the whole transaction - and do remember to NOT add it inline in the bug tracker, but upload it as a text file. Thanks. Capture from the INVITE to a couple of 200 OKs. With DEBUG and VERBOSE and SIP DEBUG - all of it.
By: Nikos Mavrogianopoulos (nmav) 2009-09-14 04:02:08

It is included in the debug.txt. I also uploaded a fix for me to retransmit ACK.
By: Tjardick van der Kraan (tjardick) 2010-02-22 03:49:27.000-0600

We just performed a test with the above patch, as we had the same issue of ACK's only being send once and if not received the first time, would result in a hangup of call.

I can confirm that the above patch resolved this issue for us.
By: Leif Madsen (lmadsen) 2011-07-26 14:23:55.617-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions

If this is still an issue, please open a new issue so it can be re-triaged appropriately. Thanks!