[Home]

Summary:ASTERISK-07207: Bridged SIP RTP stream not redirected back to asterisk due to missing REINVITE message
Reporter:Paulo Mendes da Silva (kanelbullar)Labels:
Date Opened:2006-06-20 11:03:10Date Closed:2011-06-07 14:03:03
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/RTP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) messages_sip_missing_reinvite.txt
Description:The SIP RTP stream destination is not properly changed when it is flowing peer to peer (RTP bridge) and must be redirected to go through asterisk, due to some change in the call topology.

This happens when we have SIP parties engaged in a call configured with the 'canreinvite' field set to 'yes'.

Let's take a look at the following scenario.

Step I)  Call established between X and Y
 - X and Y are SIP parties configured with 'canreinvite=yes'.
 - A call is established between X and Y.
 - X is sending its RTP stream directly to Y.
 - Y is sending its RTP stream directly to X.
Step II) Call redirected to Z
 - Z is an IAX2 party.
 - Y blindly transfers its call to Z, using the AMI Redirect action.
 - At this stage, Z should be listening to X and X should be listening to Z, but that doesn't happen.
 - Z is sending its RTP stream to asterisk, which in turn sends it to X
 - X is still sending its RTP stream to Y, even though Y has already left the call.    
 
What went wrong? Aterisk did not tell X that it should start sending its RTP stream back to asterisk. That is, asterisk did not send X a REINVITE message stating the RTP stream should be sent to asterisk instead of Y. This would allow asterisk to properly receive the RTP stream and forward it to Z, the IAX party.

The problem is exactly the same if we replace Z, an IAX party, for a Zap party or a SIP party configured with 'canreinvite=no'. That is, whenever a call that is established between to SIP parties with a peer to peer bridged RTP stream ('canreinvite=yes') and, due to some change, some part of the RTP stream must go through asterisk, so that is it properly forwarded, asterisk does not send the necessary REINVITE messages.


Attached you can find a 'sip debug' output showing the problem. You can follow the complete scenario (X=7914, Y=7910, Z=7200) and look for the comment "Missing REINVITE message", which will let you know where a REINVITE message should have been sent so as to make X send its stream to Z. You can find additional comments at that point in the file.


****** ADDITIONAL INFORMATION ******

It is also possible to reproduce this problem redirecting multiple parties to MeetMe rooms.

Step I)  Call established between X and Y
 - X and Y are SIP parties configured with 'canreinvite=yes'.
 - A call is established between X and Y.
 - X is sending its RTP stream to Y.
 - Y is sending its RTP stream to X.
Step II) Consultation call between Y to Z
 - Z is a SIP party configured with 'canreinvite=yes'.
 - X is held and listening to MOH.
 - A call is established between Y and Z.
 - X is redirected to the MeetMe room using the Redirect AMI action.
 - Z and Y are redirected to the MeetMe room using the Redirect AMI action.
 - Z and Y are talking to each other.
 - X is listening and talking to nobody.
 - Z and Y are not sending their stream to asterisk, as they did not receive any REINVITE message.


Other similar scenarios may possibly generate this problem too. The problem does not happen when a call is redirected, but there is not need to make the RTP go through asterisk. In such cases, everything works fine.

Comments:By: Serge Vecher (serge-v) 2006-06-20 11:25:58

your trace is missing debug log.
1) Make sure your logger.conf has the following line:
  console => notice,warning,error,debug
2) Restart asterisk
3) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
sip debug
4) Save complete log to file and _attach_ said file to the bug.
By: Paulo Mendes da Silva (kanelbullar) 2006-06-21 05:43:04

Attached requested file, including the comments that were added to the previous file.
By: Olle Johansson (oej) 2006-06-22 02:12:15

kanelbullar: Thanks for reporting this. I've had a similar report before that we solved, but not due to the AMI redirect action. That's very interesting. I'll try to take a look at this.
By: Olle Johansson (oej) 2006-06-22 02:13:15

Kanelbullar: The debug file does not include any debugging or logging information. Please fix that so that we can see what's going on inside your asterisk server. Thanks.
By: Paulo Mendes da Silva (kanelbullar) 2006-06-22 05:40:37

OEJ: thanks for the feedback. I have attached a new file,  "messages_sip_missing_reinvite.txt", hoping that it contains all the information you need to analyze the problem. If you need any further information, just let me know.
By: Olle Johansson (oej) 2006-06-22 10:00:59

This log actually sends a re-invite back to the server (176) after the redirect and a bye to the other call leg. Can you point out more exactly what is going wrong in this debug?
By: Olle Johansson (oej) 2006-06-22 10:02:03

un 21 11:17:04 DEBUG[4967] manager.c: Manager received command 'Redirect'
Jun 21 11:17:04 DEBUG[4967] channel.c: Soft-Hanging up channel 'SIP/7914-9313287'
Jun 21 11:17:04 DEBUG[5009] rtp.c: Oooh, got a hangup
Jun 21 11:17:04 DEBUG[5009] chan_sip.c: Sending reinvite on SIP '608ac29152d9128975c39ad555cc00a4@10.253.0.176' - It's audio soon redirected to IP 10.253.0.176
By: Paulo Mendes da Silva (kanelbullar) 2006-06-22 10:57:50

The REINVITE that you mention is quite correct, but it is being sent to the extension that is about to leave the call, after the Redirect operation (ext:7910, ip:10.2.200.189). Shortly after the REINVITE, a BYE is also sent to this extension in order to remove it from the call. What is missing is in fact the REINVITE for extension 7914 (ip:10.2.200.150), when extension 7200 (IAX) answers the redirected call.

Here is the scenario in more detail.

1) REINVITE for 7910.


Jun 21 11:17:04 DEBUG[5009] chan_sip.c: Sending reinvite on SIP '608ac29152d9128975c39ad555cc00a4@10.253.0.176' - It's audio soon redirected to IP 10.253.0.176
(...)
Jun 21 11:17:04 VERBOSE[5009] logger.c: Reliably Transmitting (no NAT) to 10.2.200.189:5060:
INVITE sip:7910@10.2.200.189:5060 SIP/2.0
Via: SIP/2.0/UDP 10.253.0.176:5060;branch=z9hG4bK198039b0;rport
From: "7914" <sip:7914@10.253.0.176>;tag=as0c84e840
To: <sip:7910@10.2.200.189:5060>;tag=00036bc97a290a9b435c8321-74ee3d98
Contact: <sip:7914@10.253.0.176>
Call-ID: 608ac29152d9128975c39ad555cc00a4@10.253.0.176
CSeq: 104 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
X-asterisk-info: SIP re-invite (RTP bridge)
Content-Type: application/sdp
Content-Length: 261

v=0
o=root 4942 4944 IN IP4 10.253.0.176
s=session
c=IN IP4 10.253.0.176
t=0 0
m=audio 12712 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -


2) BYE for 7910

Jun 21 11:17:05 VERBOSE[4963] logger.c: Reliably Transmitting (no NAT) to 10.2.200.189:5060:
BYE sip:7910@10.2.200.189:5060 SIP/2.0
Via: SIP/2.0/UDP 10.253.0.176:5060;branch=z9hG4bK56c1c61c;rport
From: "7914" <sip:7914@10.253.0.176>;tag=as0c84e840
To: <sip:7910@10.2.200.189:5060>;tag=00036bc97a290a9b435c8321-74ee3d98
Contact: <sip:7914@10.253.0.176>
Call-ID: 608ac29152d9128975c39ad555cc00a4@10.253.0.176
CSeq: 105 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0
(...)

3) Missing REINVITE for 7914.

Jun 21 11:17:05 VERBOSE[4963] logger.c: --- (9 headers 0 lines)Jun 21 11:17:05 VERBOSE[4963] logger.c: --- (9 headers 0 lines)---
Jun 21 11:17:05 DEBUG[4963] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid ASTERISK-24
Jun 21 11:17:05 DEBUG[4963] chan_sip.c: Stopping retransmission on '608ac29152d9128975c39ad555cc00a4@10.253.0.176' of Request 105: Match Found
Jun 21 11:17:05 VERBOSE[4963] logger.c: Destroying call '608ac29152d9128975c39ad555cc00a4@10.253.0.176'
Jun 21 11:17:07 DEBUG[4946] chan_iax2.c: Checking device state for device 7200
Jun 21 11:17:07 DEBUG[4946] chan_iax2.c: iax2_devicestate(7200): Found peer. What's device state of 7200? addr=2009596426, defaddr=0 maxms=0, lastms=0
Jun 21 11:17:07 DEBUG[4946] devicestate.c: Changing state for IAX2/7200 - state 2 (In use)
Jun 21 11:17:07 VERBOSE[5009] logger.c:     -- IAX2/7200-3 answered SIP/7914-9313287
Jun 21 11:17:07 DEBUG[5016] app_queue.c: Device 'IAX2/7200' changed to state '2' (In use)
Jun 21 11:17:07 DEBUG[5009] channel.c: Set channel SIP/7914-9313287 to write format ulaw
Jun 21 11:17:07 DEBUG[5009] channel.c: Scheduling timer at 0 sample intervals
Jun 21 11:17:07 DEBUG[5009] channel.c: Set channel SIP/7914-9313287 to read format ulaw

--------------------->>> At some point here, after the redirected call is answered by 7200, there should be a REINVITE message being sent to 7914, in order to make it send its RTP stream to Asterisk. That message is never sent.

Jun 21 11:17:07 DEBUG[5009] channel.c: Set channel IAX2/7200-3 to write format ulaw
Jun 21 11:17:07 DEBUG[5009] channel.c: Set channel IAX2/7200-3 to read format ulaw
Jun 21 11:17:07 DEBUG[5009] channel.c: Set channel SIP/7914-9313287 to write format ulaw
Jun 21 11:17:07 DEBUG[4954] chan_iax2.c: Ooh, voice format changed to 4
Jun 21 11:17:07 DEBUG[4954] channel.c: Set channel IAX2/7200-3 to read format ulaw
Jun 21 11:17:16 VERBOSE[4963] logger.c:

<-- SIP read from 10.2.200.150:2063:
BYE sip:7910@10.253.0.176 SIP/2.0
Via: SIP/2.0/UDP 10.2.200.150:2063;branch=z9hG4bK-7ja7tehfpya9;rport
From: "7914" <sip:7914@10.253.0.176>;tag=bck9fswnc8
To: <sip:7910@10.253.0.176;user=phone>;tag=as57f41a66
Call-ID: 3c376d536419-hh9gc75x74cz@snom320-000413242B7A
CSeq: 3 BYE
Max-Forwards: 70
Contact: <sip:7914@10.2.200.150:2063;line=v62iicjq>;flow-id=1
User-Agent: snom320/5.5
RTP-RxStat: Total_Rx_Pkts=788,Rx_Pkts=788,Rx_Pkts_Lost=65299,Remote_Rx_Pkts_Lost=0
RTP-TxStat: Total_Tx_Pkts=373,Tx_Pkts=373,Remote_Tx_Pkts=0
Content-Length: 0
By: Serge Vecher (serge-v) 2006-09-01 12:31:32

ping and did kanelbullar try 1.2.11?
By: jmls (jmls) 2006-11-01 05:58:34.000-0600

ping and did kanelbullar try 1.2.11 or 1.2.13 ??
By: Joshua C. Colp (jcolp) 2006-11-15 16:16:27.000-0600

This has been open for far too long without any reply from the reporter and I believe I even fixed this awhile back. If it is still an issue though please reopen this. Thanks!