[Home]

Summary:ASTERISK-08941: race condition in sip hangup with reinvited media
Reporter:edgreenberg (edgreenberg)Labels:
Date Opened:2007-03-05 15:42:18.000-0600Date Closed:2007-11-06 01:55:23.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Interoperability
Versions:Frequency of
Occurrence
Related
Issues:
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:+14082098516@4.55.16.99, 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:+14082098516@4.55.16.99:5060;lr
     6 11:01:04.651667 bb.bb.bb.bb           cc.cc.cc.cc           SIP/SDP  Request: INVITE sip:+14082098516@4.55.16.99: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:+14082098516@4.55.16.99:5060
    10 11:01:16.262140 bb.bb.bb.bb           cc.cc.cc.cc           SIP/SDP  Request: INVITE sip:+14082098516@4.55.16.99: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:+14082098516@4.55.16.99: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:+14082098516@4.55.16.99: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 :-)

/O