|Summary:||ASTERISK-08941: race condition in sip hangup with reinvited media|
|Date Opened:||2007-03-05 15:42:18.000-0600||Date Closed:||2007-11-06 01:55:23.000-0600|
|Environment:||Attachments:||( 0) verbosedebug.txt|
|Description:||Condition: Server A (Asterisk 1.4.1) places call on server B (1.4.1) which extends it to the provider, C (sonus)|
When Asterisk 1.4.1 reinvites, and then the call ends, it reinvites the destination end back to itself, then sends a bye without waiting for the re-invite to be complete, causing a race condition.
If we are going to re-invite (back to ourselves), we should wait for the 100 Trying, then 200 OK, then ack the 200 OK, and only then, send a bye.
****** ADDITIONAL INFORMATION ******
The order of packets is:
Asterisk is bbb.bbb.bbb.bbb and ccc.ccc.ccc.ccc is the provider.
No. Time Source Destination Protocol Info
1 11:00:55.156468 bb.bb.bb.bb cc.cc.cc.cc SIP/SDP Request: INVITE sip:+firstname.lastname@example.org, with session description
2 11:00:55.176385 cc.cc.cc.cc bb.bb.bb.bb SIP Status: 100 Trying
3 11:00:57.088130 cc.cc.cc.cc bb.bb.bb.bb SIP/SDP Status: 183 Session Progress, with session description
4 11:01:04.649416 cc.cc.cc.cc bb.bb.bb.bb SIP/SDP Status: 200 OK, with session description
5 11:01:04.650518 bb.bb.bb.bb cc.cc.cc.cc SIP Request: ACK sip:+email@example.com:5060;lr
6 11:01:04.651667 bb.bb.bb.bb cc.cc.cc.cc SIP/SDP Request: INVITE sip:+firstname.lastname@example.org:5060;lr, with session description
(This reinvites the media stream to server A)
7 11:01:04.670528 cc.cc.cc.cc bb.bb.bb.bb SIP Status: 100 Trying
8 11:01:04.693890 cc.cc.cc.cc bb.bb.bb.bb SIP/SDP Status: 200 OK, with session description
9 11:01:04.694739 bb.bb.bb.bb cc.cc.cc.cc SIP Request: ACK sip:+email@example.com:5060
10 11:01:16.262140 bb.bb.bb.bb cc.cc.cc.cc SIP/SDP Request: INVITE sip:+firstname.lastname@example.org:5060, with session description
(this reinvites the media stream back to serer B, after we receive a BYE from server A)
11 11:01:16.280924 cc.cc.cc.cc bb.bb.bb.bb SIP Status: 100 Trying
12 11:01:16.281362 bb.bb.bb.bb cc.cc.cc.cc SIP Request: BYE sip:+email@example.com:5060
(We send our BYE too early. We need to wait for, and ACK a 200 OK)
13 11:01:16.302786 cc.cc.cc.cc bb.bb.bb.bb SIP Status: 200 OK
14 11:01:16.316902 cc.cc.cc.cc bb.bb.bb.bb SIP Status: 487 Request Terminated
15 11:01:16.317364 bb.bb.bb.bb cc.cc.cc.cc SIP Request: ACK sip:+firstname.lastname@example.org:5060
16 11:01:16.807487 cc.cc.cc.cc bb.bb.bb.bb SIP Status: 487 Request Terminated
|Comments:||By: Serge Vecher (serge-v) 2007-03-05 15:58:35.000-0600|
ok, thanks for the analysis, we still need to see the debug log.
1) Prepare test environment (reduce the amount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
console => notice,warning,error,debug
3) restart Asterisk with the following command:
'asterisk -Tvvvvvdddddngc | tee /tmp/verbosedebug.txt'
4) Enable SIP transaction logging with the following CLI commands (1.4/trunk commands in parenthesis):
set debug 4 (core set debug 4)
set verbose 4 (core set verbose 4)
sip debug (sip set debug)
5) Reproduce the problem
6) Trim startup information and attach verbosedebug.txt to the issue.
By: edgreenberg (edgreenberg) 2007-03-05 16:39:08.000-0600
Tonight... when the server is quiet.
By: edgreenberg (edgreenberg) 2007-03-05 22:32:45.000-0600
After collecting the trace requested, and reviewing it, I note these interesting facts. After sending the re-invite to pull the media back to our box, the action begins around line 1271, when we receive a 100 Trying from the distant end. We seem to use that to prompt sending the BYE.
While attempting to reproduce this earlier, I had occasion to replace the distant sonus gateway with another Asterisk box. When that Asterisk box receives the reinvite, it goes directly to returning a 200 OK rather than a 100 followed by a 200. In that case, our Asterisk box under test ACKs the 200 OK before sending the BYE.
It seems to go astray in handle_response, which calls handle_response_invite.
By: Olle Johansson (oej) 2007-05-30 04:38:00
reminder to myself... This issue does not belong at the end of the list :-)
By: Curt Moore (jcmoore) 2007-09-25 13:20:35
Initial tests seem to indicate that the sip_reinvite6.diff patch in http://bugs.digium.com/view.php?id=9305 resolves this issue. Hopefully we can get some further testing and get it in to 1.4/trunk ASAP.
By: edgreenberg (edgreenberg) 2007-09-26 10:24:18
I no longer consult at the company where I discovered this, so I don't have access to those servers. Sorry I can't try to reproduce.
By: Olle Johansson (oej) 2007-11-06 01:55:22.000-0600
Duplicate of 9305 (according to jcmoore). Let's continue on that unified bug report :-)