[Home]

Summary:ASTERISK-22436: [patch] No BYE to masqueraded channel on INVITE with replaces
Reporter:Eelco Brolman (eelcob)Labels:
Date Opened:2013-09-02 07:55:00Date Closed:2015-02-08 20:45:53.000-0600
Priority:MajorRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:1.8.23.1 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Attachments:( 0) asterisk-1.8-hangup-replaced.diff
( 1) asterisk-1.8-hangup-replaced-2.diff
( 2) asterisk-11-hangup-replaced.diff
( 3) asterisk-11-hangup-replaced-2.diff
( 4) asterisk-11-hangup-replaced-3.diff
( 5) asterisk-debug.log
( 6) atrujillo-asterisk1-full-log.txt
( 7) atrujillo-asterisk1-packets.pcap
( 8) atrujillo-asterisk2-full-log.txt
( 9) atrujillo-asterisk2-packets.pcap
Description:Consider the flow as in http://www.in2eps.com/fo-sip/tk-fo-sip-service-05.html. Carol is the asterisk server in this case, Alice and Bob 2 (external) sip phones (i.e. NOT registered with asterisk). Asterisk acts for example as an application server. Bob wants to attended transfer Alice to this application.

When Bob refers Alice to Carol (asterisk), Carol (asterisk) correctly accepts the invite, and masquerades the channels into the new Invited channel.
The original channel to Bob becomes a Zombie, which is Hangup (see logging), but Asterisk fails to send out the BYE to Bob (message 22 in http://www.in2eps.com/fo-sip/tk-fo-sip-service-05.html#fig22).

This result in Bob assuming the transfer is not complete yet, and keeping the call as "on hold" on his phone.

Any thought on this issue?
{code}
[Sep  2 14:11:33] DEBUG[7190] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.29.19.13:5060
[Sep  2 14:11:33] DEBUG[7190] channel.c: Planning to masquerade channel SIP/alice-00000152 into the structure of SIP/bob-0000014f
[Sep  2 14:11:33] DEBUG[7190] channel.c: Done planning to masquerade channel SIP/alice-00000152 into the structure of SIP/bob-0000014f
[Sep  2 14:11:33] DEBUG[7190] channel.c: Putting channel SIP/alice-00000152 in alaw/alaw formats
[Sep  2 14:11:33] DEBUG[7190] chan_sip.c: SIP Fixup: New owner for dialogue 2063187328: SIP/alice-00000152 (Old parent: SIP/bob-0000014f<ZOMBIE>)
[Sep  2 14:11:33] DEBUG[7190] chan_sip.c: SIP Fixup: New owner for dialogue 54c78f06-534c5fb7-9fe652e0@172.30.19.102: SIP/bob-0000014f<ZOMBIE> (Old parent: SIP/alice-00000152)
[Sep  2 14:11:33] VERBOSE[7190] chan_sip.c: Scheduling destruction of SIP dialog '54c78f06-534c5fb7-9fe652e0@172.30.19.102' in 6400 ms (Method: ACK)
[Sep  2 14:11:33] DEBUG[7190] chan_sip.c: Session timer stopped: 68528 - 54c78f06-534c5fb7-9fe652e0@172.30.19.102
[Sep  2 14:11:33] DEBUG[7190] channel.c: Done Masquerading SIP/alice-00000152 (6)
[Sep  2 14:11:33] DEBUG[7190] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet
[Sep  2 14:11:33] DEBUG[7190] channel.c: Hanging up zombie 'SIP/bob-0000014f<ZOMBIE>'
{code}
Comments:By: Rusty Newton (rnewton) 2013-09-05 19:09:08.063-0500

Thank you for taking the time to report this bug and helping to make Asterisk better. Unfortunately, we cannot work on this bug because your description did not include enough information. You may find it helpful to read the Asterisk Issue Guidelines http://www.asterisk.org/developers/bug-guidelines. We would be grateful if you would then provide a more complete description of the problem. At a minimum, we need:

1. the specific steps or actions you took that caused you to encounter the problem,
2. the behavior you expected, and
3. the behavior you actually encountered (in as much detail as possible).

This likely includes output from the console with debug level logging, a SIP trace (if this is SIP related), and configuration information such as dialplan (e.g. extensions.conf) and channel configuration (e.g. sip.conf). Thanks!


Specifically please provide a packet capture of the complete SIP dialog, long with an Asterisk full log (VERBOSE and DEBUG) covering the whole scenario.

https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines#AsteriskIssueGuidelines-Submittingthebugreport-informationrequirements
By: Rusty Newton (rnewton) 2013-09-26 16:07:32.574-0500

Eelco, are you able to provide the additional requested information? Specifically the configuration files, full debug and packet capture?
By: Rusty Newton (rnewton) 2013-10-18 15:43:00.168-0500

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.  Further information can be found at http://www.asterisk.org/developers/bug-guidelines


By: Peter Jannesen (pjannesen) 2014-02-15 19:03:35.163-0600

In a mixed environment with multiple asterisk servers and sipxecs. We have a problem with transferring a call to a asterisk server.

After analyzing SIP traces I think that asterisk is the source of the problem.

RFC 5359 2.5 Transfer Attended gives sequence of sip messages for a attended transfer. (http://www.in2eps.com/fo-sip/tk-fo-sip-service-05.html)
In our case Alice = asterisk1, Bob = Sipxecs / tel100, Carol = asterisk2

The problem is that asterisk2 is not sending a ‘BYE’ (step 22)! So Bob (sipxecs / tel100) thinks that the transfer hangs.
If Alice and Carol are on the same asterisk server, asterisk sends a ‘BYE’!
(This is the reason that the problem only happens in a mixed environment).

This is the SIP trace (using tcpdump) of asterisk2

{noformat}
12:46:30.841478 IP (tos 0xb8, ttl 62, id 30444, offset 0, flags [none], proto UDP (17), length 1425)
   sipxecs1.5060 > asterisk2.5060: SIP, length: 1397
INVITE sip:290@asterisk2;sipxecs-lineid=6 SIP/2.0
Record-Route: <sip:sipxecs1:5060;lr;sipXecs-CallDest=UNK%2CCUST;sipXecs-rs=%2Aauth%7E.%2Afrom%7EYXM3NGI1OWQzMA%60%60%21a96cde46c4d9296fc16bc8af8b566cac>
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a8ay0sqEMEg7wr3PB5qUjbieQ
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a84WvyYTvnLCCxmGLtOh06DCQ~o9NK7RwdzsL13kThcGLS5Q
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a7bICVjhq0LXNSxCLRsexUzGg~nbM4RjAJQR56Dqn3zdL5TQ
Via: SIP/2.0/UDP 10.31.84.41:5060;branch=z9hG4bK1a7bd0b9;rport=5060
Max-Forwards: 65
From: "PJannese" <sip:Unknown@10.31.84.41>;tag=as74b59d30
To: <sip:290@sipxecs1:5060>
Contact: <sip:Unknown@10.31.84.41:5060;x-sipX-nonat>
Call-Id: 06bc46fd27fb13e447d28a6e60f57fd8@10.31.84.41:5060
Cseq: 102 INVITE
User-Agent: FPBX-2.9.0(1.8.17.0)
Date: Sat, 15 Feb 2014 11:46:30 GMT
Replaces: 7dda4502-d5ea9303-64f9de18@192.168.202.228;to-tag=as5e0e9abc;from-tag=D6F4F7B0-F96CE149
Require: replaces
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 237
Expires: 7200

v=0
o=root 1823065412 1823065412 IN IP4 10.31.84.41
s=Asterisk PBX 1.8.17.0-3
c=IN IP4 10.31.84.41
t=0 0
m=audio 15752 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

12:46:30.841958 IP (tos 0x60, ttl 64, id 5956, offset 0, flags [none], proto UDP (17), length 945)
   asterisk2.5060 > sipxecs1.5060: SIP, length: 917
SIP/2.0 100 Trying
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a8ay0sqEMEg7wr3PB5qUjbieQ;received=sipxecs1;rport=5060
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a84WvyYTvnLCCxmGLtOh06DCQ~o9NK7RwdzsL13kThcGLS5Q
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a7bICVjhq0LXNSxCLRsexUzGg~nbM4RjAJQR56Dqn3zdL5TQ
Via: SIP/2.0/UDP 10.31.84.41:5060;branch=z9hG4bK1a7bd0b9;rport=5060
Record-Route: <sip:sipxecs1:5060;lr;sipXecs-CallDest=UNK%2CCUST;sipXecs-rs=%2Aauth%7E.%2Afrom%7EYXM3NGI1OWQzMA%60%60%21a96cde46c4d9296fc16bc8af8b566cac>
From: "PJannese" <sip:Unknown@10.31.84.41>;tag=as74b59d30
To: <sip:290@sipxecs1:5060>
Call-ID: 06bc46fd27fb13e447d28a6e60f57fd8@10.31.84.41:5060
CSeq: 102 INVITE
Server: FPBX-2.9.0(1.8.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:290@asterisk2:5060>
Content-Length: 0


12:46:30.842099 IP (tos 0x60, ttl 64, id 5957, offset 0, flags [none], proto UDP (17), length 1226)
   asterisk2.5060 > sipxecs1.5060: SIP, length: 1198
SIP/2.0 200 OK
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a8ay0sqEMEg7wr3PB5qUjbieQ;received=sipxecs1;rport=5060
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a84WvyYTvnLCCxmGLtOh06DCQ~o9NK7RwdzsL13kThcGLS5Q
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a7bICVjhq0LXNSxCLRsexUzGg~nbM4RjAJQR56Dqn3zdL5TQ
Via: SIP/2.0/UDP 10.31.84.41:5060;branch=z9hG4bK1a7bd0b9;rport=5060
Record-Route: <sip:sipxecs1:5060;lr;sipXecs-CallDest=UNK%2CCUST;sipXecs-rs=%2Aauth%7E.%2Afrom%7EYXM3NGI1OWQzMA%60%60%21a96cde46c4d9296fc16bc8af8b566cac>
From: "PJannese" <sip:Unknown@10.31.84.41>;tag=as74b59d30
To: <sip:290@sipxecs1:5060>;tag=as06c41dcb
Call-ID: 06bc46fd27fb13e447d28a6e60f57fd8@10.31.84.41:5060
CSeq: 102 INVITE
Server: FPBX-2.9.0(1.8.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:290@asterisk2:5060>
Content-Type: application/sdp
Content-Length: 237

v=0
o=root 2079365558 2079365558 IN IP4 asterisk2
s=Asterisk PBX 1.8.17.0-3
c=IN IP4 asterisk2
t=0 0
m=audio 11386 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

12:46:30.884290 IP (tos 0xb8, ttl 62, id 30445, offset 0, flags [none], proto UDP (17), length 555)
   sipxecs1.5060 > asterisk2.5060: SIP, length: 527
ACK sip:290@asterisk2:5060 SIP/2.0
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6a91ST2tBteB34L13142KZ7mDA
Via: SIP/2.0/UDP 10.31.84.41:5060;branch=z9hG4bK542179db;rport=5060
Max-Forwards: 69
From: "PJannese" <sip:Unknown@10.31.84.41>;tag=as74b59d30
To: <sip:290@sipxecs1:5060>;tag=as06c41dcb
Contact: <sip:Unknown@10.31.84.41:5060;x-sipX-nonat>
Call-Id: 06bc46fd27fb13e447d28a6e60f57fd8@10.31.84.41:5060
Cseq: 102 ACK
User-Agent: FPBX-2.9.0(1.8.17.0)
Content-Length: 0
Date: Sat, 15 Feb 2014 11:46:30 GMT


.....

12:47:27.493215 IP (tos 0xb8, ttl 62, id 30447, offset 0, flags [none], proto UDP (17), length 904)
   sipxecs1.5060 > asterisk2.5060: SIP, length: 876
BYE sip:290@asterisk2:5060 SIP/2.0
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6ac0ubbst47evIg`IrWHGf1Bgw
Via: SIP/2.0/UDP 192.168.202.228;branch=z9hG4bK8ab3cacb4B715980
From: "Peter Test1" <sip:301@voip.XXXX.local>;tag=D6F4F7B0-F96CE149
To: <sip:290@voip.XXXX.local;user=phone>;tag=as5e0e9abc
Cseq: 3 BYE
Call-Id: 7dda4502-d5ea9303-64f9de18@192.168.202.228
Contact: <sip:301@192.168.202.228;x-sipX-nonat>
User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.2.6.0314
Accept-Language: nl-nl,nl;q=0.9,en;q=0.8
Max-Forwards: 69
Content-Length: 0
Date: Sat, 15 Feb 2014 11:47:27 GMT


12:47:27.493398 IP (tos 0x60, ttl 64, id 5959, offset 0, flags [none], proto UDP (17), length 603)
   asterisk2.5060 > sipxecs1.5060: SIP, length: 575
SIP/2.0 481 Call leg/transaction does not exist
Via: SIP/2.0/UDP sipxecs1;branch=z9hG4bK-XX-6ac0ubbst47evIg`IrWHGf1Bgw;received=sipxecs1;rport=5060
Via: SIP/2.0/UDP 192.168.202.228;branch=z9hG4bK8ab3cacb4B715980
From: "Peter Test1" <sip:301@voip.XXXX.local>;tag=D6F4F7B0-F96CE149
To: <sip:290@voip.XXXX.local;user=phone>;tag=as5e0e9abc
Call-ID: 7dda4502-d5ea9303-64f9de18@192.168.202.228
CSeq: 3 BYE
Server: FPBX-2.9.0(1.8.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0
{noformat}

By: Matt Jordan (mjordan) 2014-02-15 21:14:11.691-0600

A SIP trace in the comment unfortunately doesn't tell us enough.

Please attach a DEBUG log with 'sip set debug on' enabled to this issue from the Asterisk instance that fails to send the BYE request. I can reopen this issue when the log file is attached.
By: Peter Jannesen (pjannesen) 2014-02-16 16:09:15.768-0600

I have made a debug log as requested.
Hopefully you find something

By: Matt Jordan (mjordan) 2014-02-16 17:45:48.050-0600

Thanks for the log - that contains the information the issue needed.
By: Kristian Høgh (kfhdk) 2014-07-03 06:35:39.849-0500

When INVITE/Replaces is accepted, the old thannel should be hung up by sending BYE.

At line 4219 in chan_sip.c (in asterisk-1.8.23.1)
{noformat}
       } else if (p->refer && !p->alreadygone) {
               ast_debug(3, "Finally hanging up channel after transfer: %s\n", p->callid);
               stop_media_flows(p);
               transmit_request_with_auth(p, SIP_BYE, 0, XMIT_RELIABLE, 1);
               append_history(p, "ReferBYE", "Sending BYE on transferer call leg %s", p->callid);
               sip_scheddestroy(p, DEFAULT_TRANS_TIMEOUT);
{noformat}

The problem is it's the other way around.
The channel we want to hang up, is referred to by another channel.

a is talking to b.
c sends INVITE/Replaces.
p->refer->refer_call on c, is set to a.
a should be hung up, but a->refer is NULL

By: Jeremiah Gowdy (jgowdy) 2014-10-27 17:36:44.351-0500

We have experienced the same issue.  I'm asking one of our engineers to attach a full log to this case.
By: Alejandro Trujillo (atrujillo) 2014-10-27 18:09:15.479-0500

Jeremiah, Here I'm attaching full logs and packet captures on UDP and port 5060 for trying to perform an attended transfer using 2 asterisk instances and not getting BYE after INVITE with replaces.

Consider the flow as in: http://www.in2eps.com/fo-sip/tk-fo-sip-service-05.html

Based in our logs:
Alice is Extension: 80 DID: 2132013020
Bob is Extension: 81 DID: 2132013013
Carol is Extension: 87 DID: 7609336033

Our asterisk1 instance handles the communication between Alice and Bob
while our asterisk2 instance handles the communication between Bob and Carol


By: Jeremiah Gowdy (jgowdy) 2014-10-28 18:45:59.301-0500

We found it.  I'll submit a diff tomorrow.  The bug is not the code Kristian has referenced above code, which triggers on the auto-destroy.  If you patch in a flag that fixes it for the auto-destroy case, all that does is hang up on the channel 30 seconds later when the scheduler gets around to it.  What we want is for the channel to be hung up after invite replaces does the masq.

To fix the bug we simply add an ast_hangup(p->refer->refer_call->owner) to the end up handle_invite_replaces after sip_pvt_lock(p) on line 24912.

I've been advised by Corey Farrell to run the test suite since it's a patch to chan_sip.c before submitting it.  So we'll do that and then make our diff for Asterisk 1.8 and Asterisk 11.  I looked at the handle_invite_replaces code in trunk and it looks a bit different so we'll have to see if the same patch works on that version.

Thanks to Alejandro Trujillo who helped me debug this issue today.
By: Jeremiah Gowdy (jgowdy) 2014-10-29 12:13:47.507-0500

This is a small patch to hang up on the replaced channel in an Invite: Replaces scenario.  Applies to branch Asterisk 11.
By: Jeremiah Gowdy (jgowdy) 2014-10-29 12:16:14.914-0500

This is a small patch to hang up on the replaced channel in an Invite: Replaces scenario.  Applies to branch Asterisk 1.8.
By: Kristian Høgh (kfhdk) 2014-10-30 08:39:34.588-0500

When trying to compile 1.8.29 and (yes, I know its old) 11.6, I get the following:
chan_sip.c: In function ‘handle_invite_replaces’:
chan_sip.c:23033: warning: implicit declaration of function ‘ast_channel_hangup’
Am I doing something wrong?
By: Jeremiah Gowdy (jgowdy) 2014-10-30 18:54:46.740-0500

Sorry when I manually redid the patch for the different versions I typed ast_channel_hangup instead of ast_hangup.
By: Jeremiah Gowdy (jgowdy) 2014-10-30 18:56:00.740-0500

Here is the updated patch for Asterisk 11
By: Jeremiah Gowdy (jgowdy) 2014-10-30 19:13:32.551-0500

Fixed Asterisk 1.8 patch
By: Jeremiah Gowdy (jgowdy) 2014-10-31 11:24:15.494-0500

Our testing is still showing issues with this patch, just FYI.  Don't consider it production worthy yet.
By: Jeremiah Gowdy (jgowdy) 2014-10-31 14:29:52.992-0500

So the problem seems to be twofold and not really addressed by our attempted one line fix.

When we do an Invite: Replaces, we're calling ast_hangup in handle_invite_replaces on the replaced channel "c", but the ast_hangup code is checking for SIP_DEFER_BYE_ON_TRANSFER and delaying the SIP BYE for 32 seconds per DEFAULT_TRANS_TIMEOUT.  When the SIP autodestruct finally triggers 32 seconds later, p->refer is not set on the replaced channel, causing the SIP BYE to be skipped altogether.
By: Jeremiah Gowdy (jgowdy) 2014-11-03 17:59:33.737-0600

This seems to fix the issue.
By: Kristian Høgh (kfhdk) 2014-11-04 02:08:14.592-0600

asterisk-11-hangup-replaced-3.diff works for me too
By: Matt Jordan (mjordan) 2014-11-05 17:00:56.553-0600

[~jgowdy]: Do you mind putting this up for peer review on [Review Board|https://wiki.asterisk.org/wiki/display/AST/Code+Review]? Given the complexity of this one - and the fact that it involves a new flag on the {{sip_pvt}} -  it feels like this needs some more eyes on it.
By: Jeremiah Gowdy (jgowdy) 2014-11-05 17:03:53.991-0600

I agree, I'm stuck dealing with my product release deadline at the moment, but I'll get it submitted and also take a deeper look at it myself as soon as I can.  Thanks.
By: Matt Jordan (mjordan) 2015-01-19 20:10:52.161-0600

[~jgowdy]: Any chance you'd like to put this up for review? It is a new year... :-)
By: Jeremiah Gowdy (jgowdy) 2015-01-20 12:05:10.117-0600

Yeah, let me make sure what's posted here matches what we put into production.
By: Matt Jordan (mjordan) 2015-02-08 21:06:53.278-0600

[~jgowdy]: Thanks for fixing this issue - it was certainly a very tricky part of {{chan_sip}}!