[Home]

Summary:ASTERISK-19303: Asterisk does not acknowledge the ACK received to terminate the dialog.
Reporter:Jon Tsiros (ciscogeek)Labels:
Date Opened:2012-02-06 18:05:27.000-0600Date Closed:2012-03-05 09:56:19.000-0600
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:1.8.9.0 10.1.0 Frequency of
Occurrence		Constant
Related
Issues:
is duplicated byASTERISK-19313 [patch] incorrect handling of UPDATE response with canreinvite=update
Environment:OpenSUSE 11.3 Kernel 2.6.34.7-0.7 64bitAttachments:( 0) fix-19303.patch
Description:Upon receiving an invite with replaces to asterisk that does not contain the appropriate call leg, Asterisk sends a SIP/2.0 481 Call Leg Does Not Exist (Replaces), however it does not acknowledge the ACK received to terminate the dialog.

<--- SIP read from UDP:xx.xx.xx.xx:5060 --->
INVITE sip:807@xx.xx.xx.xx:5060 SIP/2.0
Record-Route: <sip:xx.xx.xx.xx;lr=on>
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
To: <sip:807@xx.xx.xx.xx>
Contact: <sip:xxxxxx92014169201@xx.xx.xx.xx>
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 69
Date: Mon, 06 Feb 2012 23:47:35 GMT
Replaces: da7731b-56d45a10-a5e4d319@xx.xx.xx.xx;to-tag=as5dd19f38;from-tag=AD72B501-CB0EBB0E
Require: replaces
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Type: application/sdp
Content-Length: 260

v=0
o=root 19893 19893 IN IP4 xx.xx.xx.xx
s=session
c=IN IP4 xx.xx.xx.xx
t=0 0
m=audio 46710 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
<------------->
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  0 [ 40]: INVITE sip:807@xx.xx.xx.xx:5060 SIP/2.0
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  1 [ 38]: Record-Route: <sip:xx.xx.xx.xx;lr=on>
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  2 [ 83]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  3 [ 57]: Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  4 [ 61]: From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  5 [ 26]: To: <sip:807@xx.xx.xx.xx>
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  6 [ 38]: Contact: <sip:xxxxxx92014169201@xx.xx.xx.xx>
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  7 [ 54]: Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  8 [ 16]: CSeq: 102 INVITE
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  9 [ 24]: User-Agent: Asterisk PBX
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 10 [ 16]: Max-Forwards: 69
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 11 [ 35]: Date: Mon, 06 Feb 2012 23:47:35 GMT
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 12 [ 92]: Replaces: da7731b-56d45a10-a5e4d319@xx.xx.xx.xx;to-tag=as5dd19f38;from-tag=AD72B501-CB0EBB0E
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 13 [ 17]: Require: replaces
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 14 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 15 [ 19]: Supported: replaces
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 16 [ 29]: Content-Type: application/sdp
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 17 [ 19]: Content-Length: 260
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 18 [  0]:
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  0 [  3]: v=0
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  1 [ 38]: o=root 19893 19893 IN IP4 xx.xx.xx.xx
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  2 [  9]: s=session
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  3 [ 21]: c=IN IP4 xx.xx.xx.xx
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  4 [  5]: t=0 0
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  5 [ 30]: m=audio 46710 RTP/AVP 0 18 101
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  6 [ 20]: a=rtpmap:0 PCMU/8000
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  7 [ 21]: a=rtpmap:18 G729/8000
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  8 [ 19]: a=fmtp:18 annexb=no
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body  9 [ 33]: a=rtpmap:101 telephone-event/8000
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body 10 [ 15]: a=fmtp:101 0-16
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:    Body 11 [ 10]: a=ptime:20
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8300 parse_request:    Body 12 [ 10]: a=sendrecv
--- (18 headers 13 lines) ---
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:7856 find_call: = Looking for  Call ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx (Checking From) --From tag as58a29384 --To-tag
[Feb  6 15:47:35] DEBUG[5391]: acl.c:725 ast_ouraddrfor: For destination 'xx.xx.xx.xx', our source address is 'xx.xx.xx.xx'.
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:3486 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address xx.xx.xx.xx:5060
 == Using UDPTL TOS bits 184
 == Using UDPTL CoS mark 5
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:4956 do_setnat: Setting NAT on UDPTL to Off
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:7536 sip_alloc: Allocating new SIP dialog for 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx - INVITE (No RTP)
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:24571 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Feb  6 15:47:35] DEBUG[5391]: sip/reqresp_parser.c:1613 parse_sip_options: Begin: parsing SIP "Supported: replaces"
[Feb  6 15:47:35] DEBUG[5391]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -replaces-
[Feb  6 15:47:35] DEBUG[5391]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: replaces
[Feb  6 15:47:35] DEBUG[5391]: sip/reqresp_parser.c:1613 parse_sip_options: Begin: parsing SIP "Supported: replaces"
[Feb  6 15:47:35] DEBUG[5391]: sip/reqresp_parser.c:1629 parse_sip_options: Found SIP option: -replaces-
[Feb  6 15:47:35] DEBUG[5391]: sip/reqresp_parser.c:1637 parse_sip_options: Matched SIP option: replaces
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:21831 handle_request_invite: INVITE part of call transfer. Replaces [da7731b-56d45a10-a5e4d319@xx.xx.xx.xx;to-tag=as5dd19f38;from-tag=AD72B501-CB0EBB0E]
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:21871 handle_request_invite: Invite/replaces: Will use Replace-Call-ID : da7731b-56d45a10-a5e4d319@xx.xx.xx.xx Fromtag: AD72B501-CB0EBB0E Totag: as5dd19f38
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:14973 get_sip_pvt_byid_locked: Looking for callid da7731b-56d45a10-a5e4d319@xx.xx.xx.xx (fromtag AD72B501-CB0EBB0E totag as5dd19f38)
[Feb  6 15:47:35] NOTICE[5391]: chan_sip.c:21898 handle_request_invite: Supervised transfer attempted to replace non-existent call id (da7731b-56d45a10-a5e4d319@xx.xx.xx.xx)!

<--- Reliably Transmitting (NAT) to xx.xx.xx.xx:5060 --->
SIP/2.0 481 Call Leg Does Not Exist (Replaces)
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4;received=xx.xx.xx.xx;rport=5060
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
CSeq: 102 INVITE
Server: Asterisk PBX 1.8.8.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


<------------>
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  0 [ 46]: SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  1 [116]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4;received=xx.xx.xx.xx;rport=5060
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  2 [ 57]: Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  3 [ 61]: From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  4 [ 41]: To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  5 [ 54]: Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  6 [ 16]: CSeq: 102 INVITE
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  7 [ 28]: Server: Asterisk PBX 1.8.8.1
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  8 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  9 [ 26]: Supported: replaces, timer
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 10 [ 17]: Content-Length: 0
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header 11 [  0]:
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:3789 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id  #30
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for xx.xx.xx.xx:5060
Scheduling destruction of SIP dialog '3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx' in 32000 ms (Method: INVITE)
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:24836 handle_request_do: SIP message could not be handled, bad request: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx

<--- SIP read from UDP:xx.xx.xx.xx:5060 --->
ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
CSeq: 102 ACK
Max-Forwards: 70
User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
Content-Length: 0

<------------->
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  0 [ 37]: ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  1 [ 83]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  2 [ 61]: From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  3 [ 54]: Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  4 [ 41]: To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  5 [ 13]: CSeq: 102 ACK
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  7 [ 47]: User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  8 [ 17]: Content-Length: 0
--- (9 headers 0 lines) ---
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:7856 find_call: = Looking for  Call ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx (Checking From) --From tag as58a29384 --To-tag as7577c919
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:24571 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb  6 15:47:35] DEBUG[5391]: chan_sip.c:24635 handle_incoming: Got ACK for unknown dialog... strange.
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:3573 retrans_pkt: SIP TIMER: Rescheduling retransmission #30 (1) SIP/2.0 - 1
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #30))
Retransmitting #1 (NAT) to xx.xx.xx.xx:5060:
SIP/2.0 481 Call Leg Does Not Exist (Replaces)
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4;received=xx.xx.xx.xx;rport=5060
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
CSeq: 102 INVITE
Server: Asterisk PBX 1.8.8.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for xx.xx.xx.xx:5060

<--- SIP read from UDP:xx.xx.xx.xx:5060 --->
ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
CSeq: 102 ACK
Max-Forwards: 70
User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
Content-Length: 0

<------------->
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  0 [ 37]: ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  1 [ 83]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  2 [ 61]: From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  3 [ 54]: Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  4 [ 41]: To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  5 [ 13]: CSeq: 102 ACK
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  7 [ 47]: User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  8 [ 17]: Content-Length: 0
--- (9 headers 0 lines) ---
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:7856 find_call: = Looking for  Call ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx (Checking From) --From tag as58a29384 --To-tag as7577c919
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:24571 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:24635 handle_incoming: Got ACK for unknown dialog... strange.
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:3573 retrans_pkt: SIP TIMER: Rescheduling retransmission #28 (9) SIP/2.0 - 1
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 10 to 4000 ms (t1 500 ms (Retrans id #28))
Retransmitting #9 (NAT) to xx.xx.xx.xx:5060:
SIP/2.0 481 Call Leg Does Not Exist (Replaces)
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKcd8e.70926e9468497d36bb75cf83527b688e.4;received=xx.xx.xx.xx;rport=5060
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK77db31fb
From: "Operator" <sip:5414087111@xx.xx.xx.xx>;tag=as047052d1
To: <sip:802@xx.xx.xx.xx>;tag=as66f9b8bf
Call-ID: 465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx
CSeq: 102 INVITE
Server: Asterisk PBX 1.8.8.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---
[Feb  6 15:47:36] DEBUG[5391]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for xx.xx.xx.xx:5060
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:3573 retrans_pkt: SIP TIMER: Rescheduling retransmission #30 (2) SIP/2.0 - 1
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #30))
Retransmitting #2 (NAT) to xx.xx.xx.xx:5060:
SIP/2.0 481 Call Leg Does Not Exist (Replaces)
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4;received=xx.xx.xx.xx;rport=5060
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
CSeq: 102 INVITE
Server: Asterisk PBX 1.8.8.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for xx.xx.xx.xx:5060

<--- SIP read from UDP:xx.xx.xx.xx:5060 --->
ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
CSeq: 102 ACK
Max-Forwards: 70
User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
Content-Length: 0

<------------->
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  0 [ 37]: ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  1 [ 83]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  2 [ 61]: From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  3 [ 54]: Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  4 [ 41]: To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  5 [ 13]: CSeq: 102 ACK
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  7 [ 47]: User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  8 [ 17]: Content-Length: 0
--- (9 headers 0 lines) ---
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:7856 find_call: = Looking for  Call ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx (Checking From) --From tag as58a29384 --To-tag as7577c919
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:24571 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb  6 15:47:37] DEBUG[5391]: chan_sip.c:24635 handle_incoming: Got ACK for unknown dialog... strange.
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:3573 retrans_pkt: SIP TIMER: Rescheduling retransmission #30 (3) SIP/2.0 - 1
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #30))
Retransmitting #3 (NAT) to xx.xx.xx.xx:5060:
SIP/2.0 481 Call Leg Does Not Exist (Replaces)
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4;received=xx.xx.xx.xx;rport=5060
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK46be18b5
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
CSeq: 102 INVITE
Server: Asterisk PBX 1.8.8.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for xx.xx.xx.xx:5060

<--- SIP read from UDP:xx.xx.xx.xx:5060 --->
ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
CSeq: 102 ACK
Max-Forwards: 70
User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
Content-Length: 0

<------------->
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  0 [ 37]: ACK sip:807@xx.xx.xx.xx:5060 SIP/2.0
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  1 [ 83]: Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bK3482.8750be818d8504d19b4fbed83c765874.4
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  2 [ 61]: From: "Operator" <sip:xxxxxx92014169201@xx.xx.xx.xx>;tag=as58a29384
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  3 [ 54]: Call-ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  4 [ 41]: To: <sip:807@xx.xx.xx.xx>;tag=as7577c919
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  5 [ 13]: CSeq: 102 ACK
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  6 [ 16]: Max-Forwards: 70
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  7 [ 47]: User-Agent: OpenSIPS (1.6.3-tls (x86_64/linux))
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:8263 parse_request:  Header  8 [ 17]: Content-Length: 0
--- (9 headers 0 lines) ---
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:7856 find_call: = Looking for  Call ID: 3bf19fbb62e1a66e72f7ed703bd15839@xx.xx.xx.xx (Checking From) --From tag as58a29384 --To-tag as7577c919
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:24571 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb  6 15:47:39] DEBUG[5391]: chan_sip.c:24635 handle_incoming: Got ACK for unknown dialog... strange.
[Feb  6 15:47:40] DEBUG[5391]: chan_sip.c:3573 retrans_pkt: SIP TIMER: Rescheduling retransmission #28 (10) SIP/2.0 - 1
[Feb  6 15:47:40] DEBUG[5391]: chan_sip.c:3593 retrans_pkt: ** SIP timers: Rescheduling retransmission 11 to 4000 ms (t1 500 ms (Retrans id #28))
Retransmitting #10 (NAT) to xx.xx.xx.xx:5060:
SIP/2.0 481 Call Leg Does Not Exist (Replaces)
Via: SIP/2.0/UDP xx.xx.xx.xx;branch=z9hG4bKcd8e.70926e9468497d36bb75cf83527b688e.4;received=xx.xx.xx.xx;rport=5060
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK77db31fb
From: "Operator" <sip:5414087111@xx.xx.xx.xx>;tag=as047052d1
To: <sip:802@xx.xx.xx.xx>;tag=as66f9b8bf
Call-ID: 465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx
CSeq: 102 INVITE
Server: Asterisk PBX 1.8.8.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0


---
[Feb  6 15:47:40] DEBUG[5391]: chan_sip.c:3332 __sip_xmit: Trying to put 'SIP/2.0 481' onto UDP socket destined for xx.xx.xx.xx:5060
[Feb  6 15:47:41] WARNING[5391]: chan_sip.c:3629 retrans_pkt: Retransmission timeout reached on transmission 465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx for seqno 102 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 32000ms with no response
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:3074 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:3876 __sip_autodestruct: Auto destroying SIP dialog '465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx'
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:5903 sip_destroy: Destroying SIP dialog 465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx
Really destroying SIP dialog '465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx' Method: ACK
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18179 sip_dump_history:
---------- SIP HISTORY for '465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx'
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18183 sip_dump_history:   * SIP Call
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   001. Rx              INVITE / 102 INVITE / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   002. TxRespRel       SIP/2.0 / 102 INVITE - 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   003. Xfer            INVITE/Replace Failed.
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   004. SchedDestroy    32000 ms
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   005. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   006. ReTx            1000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   007. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   008. ReTx            2000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   009. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   010. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   011. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   012. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   013. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   014. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   015. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   016. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   017. Rx              ACK / 102 ACK / sip:802@xx.xx.xx.xx:5060
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   018. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   019. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   020. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   021. ReTx            4000 SIP/2.0 481 Call Leg Does Not Exist (Replaces)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   022. MaxRetries      (Critical)
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   023. NeedDestroy     Setting needdestroy because no response to critical packet
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   024. DialogKill      Killing this failed dialog immediately
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18186 sip_dump_history:   025. AutoDestroy     465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx
[Feb  6 15:47:41] DEBUG[5391]: chan_sip.c:18189 sip_dump_history:
---------- END SIP HISTORY for '465a1d94689986f942e427aa27b99ac3@xx.xx.xx.xx'
Comments:By: David Woolley (davidw) 2012-02-07 11:39:56.532-0600

Are all the xx.xx.xx.xx's the same?
By: Jon Tsiros (ciscogeek) 2012-02-07 11:41:30.877-0600

yes, I've obscured them for security reasons. Look under the SIP dump history. It actually identifies the ACK as part of the dialog, it just doesn't stop the retransmission of the 481.
By: David Woolley (davidw) 2012-02-07 12:43:43.745-0600

It also says:

[Feb 6 15:47:35] DEBUG[5391]: chan_sip.c:24635 handle_incoming: Got ACK for unknown dialog... strange.

By: Jeremiah Gowdy (jgowdy) 2012-02-28 20:56:44.693-0600

This issue seems related to:

https://issues.asterisk.org/jira/browse/19371
ASTERISK-17929

But it wasn't resolved by setting pedantic = no.  Asterisk is repeatedly ignoring the ACKs and retransmitting 481s until retransmit timeout.

The client is sending a replaces header with a to-tag set, and it is also an old version of Asterisk being proxied.
By: Jeremiah Gowdy (jgowdy) 2012-02-29 02:08:01.603-0600

Actually it seems even more related to:

https://issues.asterisk.org/jira/browse/18854
ASTERISK-17445
By: Jeremiah Gowdy (jgowdy) 2012-02-29 02:32:49.870-0600

I believe the issue is that the error block of the if statement that handles INVITE (Replaces) in chan_sip.c doesn't set pendinginvite to seqno which causes the ACK to be silently ignored, keeping the retransmit timer alive despite the repeated ACKs until the SIP destroy timer fires.  I recommend:

               if (error) {    /* Give up this dialog */
                       p->pendinginvite = seqno;
                       check_via(p, req);
                       copy_request(&p->initreq, req);         /* Save this INVITE as the transaction basis */

So that this doesn't ignore the ACK:

       case SIP_ACK:
               /* Make sure we don't ignore this */
               if (seqno == p->pendinginvite) {
                       p->invitestate = INV_TERMINATED;
                       p->pendinginvite = 0;
                       acked = __sip_ack(p, seqno, 1 /* response */, 0);
                       if (find_sdp(req)) {
                               if (process_sdp(p, req, SDP_T38_NONE))
                                       return -1;
                       }
                       check_pendings(p);
By: Jeremiah Gowdy (jgowdy) 2012-02-29 02:33:56.995-0600

Oh, and I'm copying the req to p-initreq to satisfy the SIP pedantic check because we'd rather not disable that flag just to avoid triggering on this bug.
By: Richard Mudgett (rmudgett) 2012-02-29 10:46:31.045-0600

Jeremiah please use the JIRA issue reference identifiers instead of the old Mantis numbers. i.e.:
ASTERISK-17929
ASTERISK-17445

JIRA converts them to hot links automatically and even indicates if the referenced issue is closed.

Thanks
By: Jeremiah Gowdy (jgowdy) 2012-02-29 11:53:37.204-0600

Thanks for the information, this is my first Asterisk feedback.
By: Jeremiah Gowdy (jgowdy) 2012-02-29 12:03:29.874-0600

We have verified that this patch fixes the issue.
By: Jeremiah Gowdy (jgowdy) 2012-02-29 12:20:09.833-0600

This actually seems to apply to the entire section of errors with transmit_response_reliable in the first half of handle_request_invite.  It doesn't copy req to initreq and doesn't set pendinginvite, which on handle_incoming of SIP_ACK first makes SIP pedantic unhappy thinking the ACK isn't associated with an existing dialog, and even with pedantic off the lack of pendinginvite causes handle_incoming to discard the ACK rather than calling __sip_ack.
By: Kinsey Moore (kmoore) 2012-03-05 10:02:39.624-0600

I applied this fix to the other reliable retransmissions in handle_request_invite and committed.  In the future, please submit patches in unified diff format (diff -u) or use 'svn diff' to generate diffs.  Thanks for tracking this down!