[Home]

Summary:ASTERISK-23318: CLONE - ACK sent to wrong destination in CANCEL dialog
Reporter:Gregory J Borrelli (borrellinet)Labels:
Date Opened:2014-02-16 19:40:50.000-0600Date Closed:2014-02-16 20:10:29.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:
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: