onSuccess never called, JsSIP stalled #257

mEkblom · 2014-10-22T13:58:19Z

JsSIP stopped working in FF33. We are using WebRTC without STUN servers and the problem was caused by the different way ICE candidates are trickling in FF and Chrome.

In Chrome this happens:

An offer SDP is created
iceGatheringState is gathering
The local description is set and onSetLocalDescriptionSuccess is called
ICE candidates come trickling in
iceGatheringState change to complete with the last candidate being null

In JsSIP you rely on the onIceCompleted method of the RTCMediaHandler to be called after step 4 when the onicecandidate event happens. This works fine in Chrome.

In Firefox this happens:

An offer SDP is created
onicecandidate is fired with a null candidate because all candidates are already in the SDP (onIceCompleted not defined and not called)
iceGatheringState is complete since all candidates are in the SDP
The local description is set and onSetLocalDescriptionSuccess is called

The problem here is that JsSIP onicecandidate is fired before onIceCompleted has been defined (because the local description has not been set). Also the preventive check if all candidates have already been created and the iceGatheringState is complete fails because iceConnectionState is supposed to be connected.

In the code onSuccess is never called and JsSIP stalls. By removing the requirement that iceConnectionState is connected (not sure why this requirement is there, during this phase you can't expect connection to be ready, no remote SDP has been set, as far as I can see), it worked. At this stage the iceConnectionState is new which seems to be reasonable.

Also this is for the SDP offer process, I would expect similar problems for the SDP answer process (when the iceConnectionState is checking if I don't remember wrong).

Suggested solution in the pull request, solved the issue for us.

ibc · 2014-10-22T14:02:01Z

Thanks, let's us know inspect it.

jmillan · 2014-10-24T07:52:05Z

Hi,

Tested in FF nightly (35.0a) it's got the expected behaviour.

This is a log of an offer creation:

`
createOffer..." jssip-devel.js:142
iceGatheringState: complete. iceConnectionState: new" jssip-devel.js:142

setLocalDescription..." jssip-devel.js:142
iceGatheringState: complete. iceConnectionState: new" jssip-devel.js:142

onSetLocalDescriptionSuccess..." jssip-devel.js:142
iceGatheringState: complete. iceConnectionState: new" jssip-devel.js:142
SDP not ready to be sent. Waiting for the last Ice candidate.." jssip-devel.js:142

ICE candidate received: candidate:0 1 UDP 2130379007 192.168.100.101 54499 typ host" jssip-devel.js:142
ICE candidate received: candidate:1 1 UDP 2130379007 192.168.1.4 61818 typ host" jssip-devel.js:142
ICE candidate received: candidate:2 1 UDP 2129723647 192.168.169.1 65285 typ host" jssip-devel.js:142
ICE candidate received: candidate:3 1 UDP 2129264895 172.16.114.1 64216 typ host" jssip-devel.js:142
ICE candidate received: candidate:0 2 UDP 2130379006 192.168.100.101 61980 typ host" jssip-devel.js:142
ICE candidate received: candidate:1 2 UDP 2130379006 192.168.1.4 50099 typ host" jssip-devel.js:142
ICE candidate received: candidate:2 2 UDP 2129723646 192.168.169.1 49370 typ host" jssip-devel.js:142
ICE candidate received: candidate:3 2 UDP 2129264894 172.16.114.1 49499 typ host" jssip-devel.js:142

onIceCompleted..." jssip-devel.js:142
SDP ready to be sent"
`

As seen in the previous log, the ICE gathering is triggered by setLocalDescription after its success callback is fired (onSetLocalDescriptionSuccees). So by the time the last ICE candidate is gathered, the onIceCompleted callback has been defined.

So, even if the iceGatheringState is said to be completed from the beginning, the candidates are really gathered after setLocalDescription success callback is fired, and the last candidate fires the onIceCompleted.

I'll have to check the sequence of the events on FF33 though.

jmillan · 2014-10-24T07:59:57Z

As a side note; the previously commented behaviour (in FF35) corresponds with the latests WebRTC editors draft.

jmillan · 2014-10-24T08:40:23Z

More notes...

Tested in FF33, the flow is the following:

``
createOffer..." jssip-devel.js:142
iceGatheringState: complete. iceConnectionState: new" jssip-devel.js:142

setLocalDescription..." jssip-devel.js:142
iceGatheringState: complete. iceConnectionState: new" jssip-devel.js:142

peerConnection.onicecandidate..." jssip-devel.js:142
(single onicecandidate with NULL candidate)

onSetLocalDescriptionSuccess..." jssip-devel.js:142
iceGatheringState: complete. iceConnectionState: new" jssip-devel.js:142
SDP not ready to be sent. Waiting for the last Ice candidate.."
``

The difference between 33 and 35 versions is that in 33 ICE candidates seem to be in memory and thus, the Gathering is instantaneous, making the peerConnection.onicecandidate with empty candidate be fired before the success callback of peerConnection.setLocalDescription is fired.

Chrome does behave the same way FF35 does, with the difference that Chrome sets the iceGatheringState to new, until the it is actually done.

ibc · 2014-10-24T10:53:49Z

Hi all, may we clarify the current status of this issue? AFAIU:

This is a bug in FF33 fixes in FF35.
FF35 adheres to the latest WebRTC spec while FF33 does not.

Am I right?

jmillan · 2014-10-24T11:00:17Z

I don't see that calling onicecandidate before the setLocalDescription success callback is a bug, according to the spec.

In the case of FF33, the candidates are already cached, so no gathering is really done. JsSIP expects the setLocalDescription success callback to be fired before the last ICE candidate is gathered, so we should be prepared for that.

ibc · 2014-10-24T11:05:30Z

OK, does the path included in this PR fixes that? I don't like it too much (I do want to rely on the iceConnectionState).

What about firing onicecandidate in a next tick?:

Now:

this.peerConnection.onicecandidate = function(e) {
      if (e.candidate) {
        self.logger.debug('ICE candidate received: '+ e.candidate.candidate);
      } else if (self.onIceCompleted !== undefined) {
        self.onIceCompleted();
      }
};

Proposal:

this.peerConnection.onicecandidate = function(e) {
  setTimeout(function() {
      if (e.candidate) {
        self.logger.debug('ICE candidate received: '+ e.candidate.candidate);
      } else if (self.onIceCompleted !== undefined) {
        self.onIceCompleted();
      }
  });
};

jmillan · 2014-10-24T11:51:48Z

I find it perfect @ibc

ibc · 2014-10-24T11:52:19Z

Will commit right now.

…race conditions in FF33 (#257)

ibc · 2014-10-24T12:00:49Z

@mEkblom could you please check master and verify whether ca7702e fixes the issue in FF33?

jmillan · 2014-10-24T12:02:32Z

I already did it. We can close this issue.

Thanks a lot!

ibc · 2014-10-24T12:03:01Z

Great!

mEkblom · 2014-11-06T14:17:25Z

I have to say that this solution seems a little odd to me. The timeout feels more like a hack than a solution.

I suppose you still check if the iceConnectionState will be connected or completed (removing the condition was my proposed and working solution). This will never happen during ice gathering, the state will be either connecting (creating offer) or checking (creating answer) since the SDP has not been set yet.

If you now rely on the timeout fix you should probably remove the if clause since it can and will never happen (correct me if I'm wrong).

Relying on iceGatheringState is complete (ie, not gathering anymore, regardless of iceConnectionState) should be sufficient and works in my implementation. A better solution in my opinion.

jmillan · 2014-11-10T13:57:50Z

It is true. I can't remember which was the reason to put the iceConnectionState conditions there but they are not needed anymore. The iceGatheringState suffices to know whether we are ready to send the offer/answer or not

jmillan · 2014-11-10T13:58:56Z

Also, after trying FF stable again I can see that it sometimes don't fire onicecandidate at all.

@mEkblom

Credits to @mEkblom

mEkblom · 2014-11-11T14:51:47Z

OT, in my opinion the real cause of this problem is the odd decision in the Chrome implementation to use onicecandidate with a null candidate as a way to say that gathering has finished and that iceGatheringState is complete.

Much better would be to have to use an onicegatheringstatechange event (analogue to oniceconnectionstatechange) to monitor state changes during the gathering process. This would be trivial to implement in browsers and FF already had this functionality earlier with the ongatheringchange.

Unfortunately, it seems the null-candidate approach has found it's way into the upcoming standard. What a shame to drop a good solution.

onSuccess never called, connection state new or checking

aa82205

mEkblom mentioned this pull request Oct 23, 2014

ICE connection does not complete #258

Closed

ibc added a commit that referenced this pull request Oct 24, 2014

- RTCMediaHandler: fire onIceCompleted() on next tick to avoid event …

ca7702e

…race conditions in FF33 (#257)

ibc closed this Oct 24, 2014

jmillan added a commit that referenced this pull request Nov 10, 2014

Fix #257. Rely only on iceGatheringState to retrieve the offer/answer.

3bbbe0f

Credits to @mEkblom

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

onSuccess never called, JsSIP stalled #257

onSuccess never called, JsSIP stalled #257

mEkblom commented Oct 22, 2014

ibc commented Oct 22, 2014

jmillan commented Oct 24, 2014

jmillan commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

ibc commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

mEkblom commented Nov 6, 2014

jmillan commented Nov 10, 2014

jmillan commented Nov 10, 2014

mEkblom commented Nov 11, 2014

onSuccess never called, JsSIP stalled #257

onSuccess never called, JsSIP stalled #257

Conversation

mEkblom commented Oct 22, 2014

ibc commented Oct 22, 2014

jmillan commented Oct 24, 2014

jmillan commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

ibc commented Oct 24, 2014

jmillan commented Oct 24, 2014

ibc commented Oct 24, 2014

mEkblom commented Nov 6, 2014

jmillan commented Nov 10, 2014

jmillan commented Nov 10, 2014

mEkblom commented Nov 11, 2014