| Summary: | ASTERISK-23313: ACK sent to wrong destination in CANCEL dialog | ||||||
| Reporter: | Gregory J Borrelli (borrellinet) | Labels: | |||||
| Date Opened: | 2014-02-14 12:34:36.000-0600 | Date Closed: | 2014-02-16 18:40:49.000-0600 | ||||
| Priority: | Critical | Regression? | |||||
| Status: | Closed/Complete | Components: | Channels/chan_sip/General | ||||
| Versions: | 11.7.0 | Frequency of Occurrence | Constant | ||||
| Related Issues: |
| ||||||
| Environment: | FreePBX 2.11.0.23, CentOS 6.5 (2.6.32-431.el6.i686), Asterisk 11.7.0 | Attachments: | ( 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: Matt Jordan (mjordan) 2014-02-14 16:14:49.167-0600 Based on the logs, I don't see the bug you've described. Asterisk appears to be doing the correct thing: # We transmit the INVITE request to 64.2.142.93:5060: {noformat} [2014-02-14 13:05:43] VERBOSE[15926][C-000000f4] chan_sip.c: Reliably Transmitting (no NAT) to 64.2.142.93:5060: �INVITE sip:12032649261@64.2.142.93 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> �Contact: <sip:8609150274@108.244.232.196:5060> �Call-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060 �CSeq: 102 INVITE �User-Agent: FPBX-2.11.0(11.7.0) �Date: Fri, 14 Feb 2014 18:05:43 GMT �Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH �Supported: replaces, timer �Remote-Party-ID: "BORRELLINET IT L1" <sip:8609150274@108.244.232.196>;party=calling;privacy=off;screen=no �Content-Type: application/sdp �Content-Length: 241 � �v=0 �o=root 1068114121 1068114121 IN IP4 108.244.232.196 �s=Asterisk PBX 11.7.0 �c=IN IP4 108.244.232.196 �t=0 0 �m=audio 11836 RTP/AVP 0 101 �a=rtpmap:0 PCMU/8000 �a=rtpmap:101 telephone-event/8000 �a=fmtp:101 0-16 �a=ptime:20 �a=sendrecv � �--- {noformat} # When the INVITE request is cancelled due to the inbound channel terminating the dial attempt, we transmit the CANCEL request to 64.2.142.93: {noformat} [2014-02-14 13:05:58] VERBOSE[15926][C-000000f4] chan_sip.c: Reliably Transmitting (no NAT) to 64.2.142.93:5060: �CANCEL sip:12032649261@64.2.142.93 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> �Call-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060 �CSeq: 102 CANCEL �User-Agent: FPBX-2.11.0(11.7.0) �Content-Length: 0 {noformat} # We read back from 64.2.142.93:5060 a 200 OK to our CANCEL request: {noformat} �<--- SIP read from UDP:64.2.142.93:5060 ---> �SIP/2.0 200 canceling �Via: SIP/2.0/UDP 108.244.232.196:5060;branch=z9hG4bK0deea205;rport=5060 �From: "BORRELLINET IT L1" <sip:8609150274@108.244.232.196>;tag=as7cabff0c �To: <sip:12032649261@64.2.142.93>;tag=d8ec4bef69e0ea2b5541b4b24b7b56ef-9b77 �Call-ID: 461c637f587aa81f64b6316c73e221fe@108.244.232.196:5060 �CSeq: 102 CANCEL �Server: OpenSIPS (1.6.4-2-notls (x86_64/linux)) �Content-Length: 0 {noformat} # We then read a 487 for the INVITE request: {noformat} �<--- SIP read from UDP:64.2.142.93:5060 ---> �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 � �<-------------> {noformat} # We then correctly send the ACK to the INVITE request's 487 response to 64.2.142.93:5060: {noformat} [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 � � �--- {noformat} Based on your bug description, I would expect that the ACK sent to the 487 response would have been sent to a different address than the INVITE request that resulted in the 487 response; however, the log file does not show that. By: Gregory J Borrelli (borrellinet) 2014-02-14 16:48:39.119-0600 It's the actual ACK header that is wrong: -> ACK sip:12032649261@66.241.96.140 SIP/2.0 66.241.96.140 (their RTP/media server) should be 64.2.142.93 (the SIP proxy that the original INVITE was sent to): -> INVITE sip:12032649261@64.2.142.93 SIP/2.0 By: Matt Jordan (mjordan) 2014-02-16 18:38:32.707-0600 The problem is, your endpoint changed the Contact address in the 183: {noformat} [2014-02-14 13:05:45] VERBOSE[2013] chan_sip.c: �<--- SIP read from UDP:64.2.142.93:5060 ---> �SIP/2.0 183 Session Progress �Via: SIP/2.0/UDP 108.244.232.196:5060;rport=5060;received=108.244.232.196;branch=z9hG4bK0deea205 �Record-Route: <sip:64.2.142.93;lr=on> �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 �Contact: <sip:12032649261@66.241.96.140> �Content-Type: application/sdp �Content-Length: 242 � �v=0 �o=root 24046 24046 IN IP4 66.241.96.140 �s=session �c=IN IP4 66.241.96.140 �t=0 0 �m=audio 19450 RTP/AVP 0 101 �a=rtpmap:0 PCMU/8000 �a=rtpmap:101 telephone-event/8000 �a=fmtp:101 0-16 �a=silenceSupp:off - - - - �a=ptime:20 �a=sendrecv �<-------------> {noformat} Note the Contact header there is the 62.2.142.93 address, not the address that the INVITE request was sent to. This makes things ... weird. From Section 8.1.1.8: {quote} 8.1.1.8 Contact The Contact header field provides a SIP or SIPS URI that can be used to contact that specific instance of the UA for subsequent requests. The Contact header field MUST be present and contain exactly one SIP or SIPS URI in any request that can result in the establishment of a dialog. For the methods defined in this specification, that includes only the INVITE request. For these requests, the scope of the Contact is global. That is, the Contact header field value contains the URI at which the UA would like to receive requests, and this URI MUST be valid even if used in subsequent requests outside of any dialogs. {quote} This makes everything very confusing. Your proxy has informed Asterisk that it wants to be contacted at {{sip:12032649261@66.241.96.140}}. So, what takes precedence - the INVITE request line, or what the proxy told us to send to in the 1xx provisional response? In this case, I still think Asterisk is doing the right thing. # The ACK request is sent to the URI specified in the provisional response. # However, the ACK request is transmitted to the IP address and port that the INVITE request was sent to. Note that this is inline with 17.1.1.2, which - in full context - states: {quote} The client transaction MUST pass the received response up to the TU, and the client transaction MUST generate an ACK request, even if the transport is reliable (guidelines for constructing the ACK from the response are given in Section 17.1.1.3) and then pass the ACK to the transport layer for transmission. The ACK MUST be sent to the same address, port, and transport to which the original request was sent. {quote} Note that this is referring to the transport layer - and Asterisk did, in fact, send the ACK request to the correct IP address and port number (even if the request line includes the URI specified by your proxy). Even *if* there was a bug here in Asterisk, this could probably be easily solved by your proxy not telling Asterisk to contact it at the RTP media address. By: Matt Jordan (mjordan) 2014-02-16 18:40:49.611-0600 Barring additional input from other bug marshals, I'm going to close this out as "Not a Bug". If you'd like to discuss this behaviour further, I'd recommend starting a thread on the {{asterisk-dev}} mailing list. More people can weigh in on whether or not this is actually a bug. If the consensus is that this is a bug, I'd be happy to reopen this issue. By: Gregory J Borrelli (borrellinet) 2014-02-16 18:59:18.001-0600 I still think this is a bug... I don't think the Record-Route 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. By: Gregory J Borrelli (borrellinet) 2014-02-16 20:08:46.127-0600 I've attached another SIP trace, 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. | ||||||