[Home]

Summary:ASTERISK-23317: CLONE - ACK sent to wrong destination in CANCEL dialog
Reporter:Gregory J Borrelli (borrellinet)Labels:
Date Opened:2014-02-16 19:40:36.000-0600Date Closed:2014-02-17 06:09:57.000-0600
Priority:CriticalRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:11.7.0 Frequency of
Occurrence		Constant
Related
Issues:
is the original version of this clone:ASTERISK-23313 ACK sent to wrong destination in CANCEL dialog
Environment:FreePBX 2.11.0.23, CentOS 6.5 (2.6.32-431.el6.i686), Asterisk 11.7.0Attachments:( 0) ack_issue_ex2.txt
( 1) ack_issue.pcap
( 2) asterisk_debug_log.txt
( 3) sip_only.txt
Description:I've run into an issue that appears to be a bug within Asterisk. The issue surfaces when interfacing with a SIP trunk provider that uses different servers for SIP/signaling and RTP/media. I've tested against two different providers that have this type of setup and was able to consistently reproduce the problem every time.

The issue occurs when an extension on the Asterisk box makes an external call and then hangs up during the ring phase (originator cancel). All goes as expected until the very last exchange... Provider's proxy sends "487 Request Terminated" to Asterisk. It appears that Asterisk knows it’s supposed to send the ACK back to the proxy, and from a network routing perspective the packet does get sent there, but when actually constructing the ACK statement in the SIP dialog it uses the wrong IP (the IP of the provider's media server rather than the proxy server).

As per RFC 3261, Section 17.1.1.2:

"...reception of a response with status code from 300-699 MUST cause the client transaction to transition to "Completed." ... and the client transaction must generate an ACK request ... The ACK MUST be sent to the same address, port, and transport to which the original request was sent."

So it appears that asterisk is not following protocol here.

I've pasted the relevant parts of the SIP dialog and asterisk logs below for quick reference and will attach the full files as well. Let me know if any additional information is needed.


SIP DIALOG:

{noformat}
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 108.244.232.196:5060;rport=5060;received=108.244.232.196;branch=z9hG4bK0deea205
From: "BORRELLINET IT L1" <sip:8609150274@108.244.232.196>;tag=as7cabff0c
To: <sip:12032649261@64.2.142.93>;tag=as10ab2210
Call-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060
CSeq: 102 INVITE
User-Agent: packetrino
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0


ACK sip:12032649261@66.241.96.140 SIP/2.0
Via: SIP/2.0/UDP 108.244.232.196:5060;branch=z9hG4bK0deea205
Max-Forwards: 70
From: "BORRELLINET IT L1" <sip:8609150274@108.244.232.196>;tag=as7cabff0c
To: <sip:12032649261@64.2.142.93>;tag=as10ab2210
Contact: <sip:8609150274@108.244.232.196:5060>
Call-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060
CSeq: 102 ACK
User-Agent: FPBX-2.11.0(11.7.0)
Content-Length: 0
{noformat}

ASTERISK DEBUG LOG:

{noformat}
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  0 [ 30]: SIP/2.0 487 Request Terminated
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  1 [ 96]: Via: SIP/2.0/UDP 108.244.232.196:5060;rport=5060;received=108.244.232.196;branch=z9hG4bK0deea205
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  2 [ 73]: From: "BORRELLINET IT L1" <sip:8609150274@108.244.232.196>;tag=as7cabff0c
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  3 [ 48]: To: <sip:12032649261@64.2.142.93>;tag=as10ab2210
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  4 [ 62]: Call-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  5 [ 16]: CSeq: 102 INVITE
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  6 [ 22]: User-Agent: packetrino
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  7 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  8 [ 19]: Supported: replaces
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c:  Header  9 [ 17]: Content-Length: 0
[2014-02-14 13:05:58] VERBOSE[2013] chan_sip.c: --- (10 headers 0 lines) ---
[2014-02-14 13:05:58] DEBUG[2013] chan_sip.c: = Looking for  Call ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060 (Checking To) --From tag as7cabff0c --To-tag as10ab2210  
[2014-02-14 13:05:58] DEBUG[2013][C-000000f4] chan_sip.c: Stopping retransmission on '461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060' of Request 102: Match Found
[2014-02-14 13:05:58] DEBUG[2013][C-000000f4] chan_sip.c: SIP response 487 to standard invite
[2014-02-14 13:05:58] VERBOSE[2013][C-000000f4] chan_sip.c: Transmitting (no NAT) to 64.2.142.93:5060:
ÿACK sip:12032649261@66.241.96.140 SIP/2.0
ÿVia: SIP/2.0/UDP 108.244.232.196:5060;branch=z9hG4bK0deea205
ÿMax-Forwards: 70
ÿFrom: "BORRELLINET IT L1" <sip:8609150274@108.244.232.196>;tag=as7cabff0c
ÿTo: <sip:12032649261@64.2.142.93>;tag=as10ab2210
ÿContact: <sip:8609150274@108.244.232.196:5060>
ÿCall-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060
ÿCSeq: 102 ACK
ÿUser-Agent: FPBX-2.11.0(11.7.0)
ÿContent-Length: 0
ÿ
ÿ
ÿ---
[2014-02-14 13:05:58] DEBUG[2013][C-000000f4] chan_sip.c: Trying to put 'ACK sip:120' onto UDP socket destined for 64.2.142.93:5060
[2014-02-14 13:05:58] DEBUG[2013][C-000000f4] chan_sip.c: Updating call counter for outgoing call
[2014-02-14 13:05:58] VERBOSE[2013][C-000000f4] chan_sip.c: Scheduling destruction of SIP dialog '461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060' in 6400 ms (Method: INVITE)
{noformat}
Comments:By: Gregory J Borrelli (borrellinet) 2014-02-16 20:13:31.604-0600

I still think this is a bug... I don't think the contact header should modify the ACK in this way. It makes no sense how Asterisk is doing it right now. All other aspects of the ACK are saying "to: 64.2.142.93" except the actual ACK line saying "to: 66.241.96.140". And yes, Asterisk does in fact send the ACK request to the "correct" IP address and port number, but the proxy server ignores it because the request line has the wrong IP... it's useless when sent out like this.

I've attached another SIP trace (ack_issue_ex2.txt), if you wouldn't mind taking a look. Completely, different carrier but same type of setup with different servers for SIP/signaling and RTP/media. Contact header is not changed in the 183, but still Asterisk sends the ACK to the wrong IP.
By: Matt Jordan (mjordan) 2014-02-17 06:09:57.550-0600

# The log shows the same information as the original issue. The ACK is sent to the correct IP address/port number, but the request line in the ACK contains the last URI specified by the contact header header of the last response received by the endpoint. I don't think this is a bug.
# I already asked that if you felt like this was a bug to involve additional people via the asterisk-dev mailing list. I asked this because, if you feel this is still a bug, the best way to get additional input is to go to the mailing list - more people will read it than the issue tracker. Please do not create duplicate or cloned issues. That only makes it more difficult for everyone.