Closed Bug 1020024 Opened 5 years ago Closed 5 years ago

Intermittent (test_ipc.html) test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html, test_dataChannel_bug1013809.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' (and more)

Categories

(Core :: WebRTC, defect)

x86_64
Gonk (Firefox OS)
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla33
Tracking Status
firefox31 --- unaffected
firefox32 --- fixed
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- unaffected
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: KWierso, Assigned: drno)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 2 obsolete files)

https://tbpl.mozilla.org/php/getParsedLog.php?id=40989191&tree=Mozilla-Inbound
b2g_emulator_vm mozilla-inbound opt test mochitest-7 on 2014-06-03 15:04:33 PDT for push ec411f0ce167

slave: tst-linux64-spot-923




15:11:30     INFO -  39 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_LOCAL_CREATE_OFFER
15:11:30     INFO -  40 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Got offer: {"type":"offer","sdp":"v=0\r\no=Mozilla-SIPUA-32.0a1 21510 0 IN IP4 0.0.0.0\r\ns=SIP Call\r\nt=0 0\r\na=ice-ufrag:bd765c76\r\na=ice-pwd:c86608ac01e4a53cfd6b4ff3a25e329f\r\na=fingerprint:sha-256 6D:37:99:D7:C6:E2:DC:43:68:2A:21:F0:09:C6:44:44:19:44:5D:4C:FF:F1:31:31:7D:A9:77:98:92:D5:AC:94\r\nm=application 59890 DTLS/SCTP 5000\r\nc=IN IP4 10.0.2.100\r\na=sctpmap:5000 webrtc-datachannel 16\r\na=setup:actpass\r\na=candidate:0 1 UDP 2122252543 10.0.2.100 59890 typ host\r\n"}
15:11:30     INFO -  41 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Local create offer does not change signaling state
15:11:30     INFO -  42 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | m=application is contained in the SDP
15:11:30     INFO -  43 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_LOCAL_SET_LOCAL_DESCRIPTION
15:11:30     INFO -  44 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event fired
15:11:30     INFO -  45 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event 'have-local-offer' received
15:11:30     INFO -  46 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): Successfully set the local description
15:11:30     INFO -  47 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | signalingState after local setLocalDescription is 'have-local-offer'
15:11:30     INFO -  48 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_REMOTE_SET_REMOTE_DESCRIPTION
15:11:30     INFO -  49 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): 'onsignalingstatechange' event fired
15:11:30     INFO -  50 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): 'onsignalingstatechange' event 'have-remote-offer' received
15:11:30     INFO -  51 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): Successfully set remote description
15:11:30     INFO -  52 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | signalingState after remote setRemoteDescription is 'have-remote-offer'
15:11:30     INFO -  53 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_REMOTE_CREATE_ANSWER
15:11:30     INFO -  54 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): Got answer: {"type":"answer","sdp":"v=0\r\no=Mozilla-SIPUA-32.0a1 11410 0 IN IP4 0.0.0.0\r\ns=SIP Call\r\nt=0 0\r\na=ice-ufrag:ab0f0bad\r\na=ice-pwd:5e2ff1643842a0b6ea08946dff328dd9\r\na=fingerprint:sha-256 4C:BC:E9:E5:6E:C0:23:F0:C3:81:9D:07:02:6A:39:1B:E4:8A:1B:CD:B8:B3:1A:4B:83:A8:ED:56:A1:DA:2B:DE\r\nm=application 35814 DTLS/SCTP 5000\r\nc=IN IP4 10.0.2.100\r\na=sctpmap:5000 webrtc-datachannel 16\r\na=setup:active\r\na=candidate:0 1 UDP 2122252543 10.0.2.100 35814 typ host\r\n"}
15:11:30     INFO -  55 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Remote create offer does not change signaling state
15:11:30     INFO -  56 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_LOCAL_SETUP_DATA_CHANNEL_CALLBACK
15:11:30     INFO -  57 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_REMOTE_SETUP_DATA_CHANNEL_CALLBACK
15:11:30     INFO -  58 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): Register callbacks for 'ondatachannel' and 'onopen'
15:11:30     INFO -  59 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_REMOTE_SET_LOCAL_DESCRIPTION
15:11:30     INFO -  60 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | iceConnectionState should not be undefined
15:11:30     INFO -  61 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: checking
15:11:30     INFO -  62 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): 'onsignalingstatechange' event fired
15:11:30     INFO -  63 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): 'onsignalingstatechange' event 'stable' received
15:11:30     INFO -  64 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): Successfully set the local description
15:11:30     INFO -  65 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | signalingState after remote setLocalDescription is 'stable'
15:11:30     INFO -  66 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_LOCAL_SET_REMOTE_DESCRIPTION
15:11:30     INFO -  67 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | iceConnectionState should not be undefined
15:11:30     INFO -  68 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: checking
15:11:30     INFO -  69 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event fired
15:11:30     INFO -  70 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event 'stable' received
15:11:30     INFO -  71 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): Successfully set remote description
15:11:30     INFO -  72 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | signalingState after local setRemoteDescription is 'stable'
15:11:30     INFO -  73 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Run step: PC_LOCAL_VERIFY_DATA_CHANNEL_STATE
15:11:30     INFO -  74 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | iceConnectionState should not be undefined
15:11:30     INFO -  75 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: failed
15:11:30     INFO -  76 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | iceConnectionState should not be undefined
15:11:30     INFO -  77 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: connected
15:11:30     INFO -  78 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) timed out while waiting for dataChannels[0] to connect
15:11:30     INFO -  79 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open'
15:11:30     INFO -  80 INFO TEST-INFO | dumping last 1 message(s)
15:11:30     INFO -  81 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
15:11:30     INFO -  82 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote) timed out while waiting for dataChannels[0] to connect
15:11:30     INFO -  83 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote) initial dataChannels[0] failed to switch to 'open'
15:11:30     INFO -  84 INFO TEST-INFO | dumping last 1 message(s)
15:11:30     INFO -  85 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
15:11:30     INFO -  86 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) timed out while waiting for dataChannels[0] to connect
15:11:30     INFO -  87 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open'
15:12:30     INFO -  *** UTM:SVC TimerManager:notify - notified timerID: user-agent-updates-timer
15:12:31     INFO -  *** UTM:SVC TimerManager:registerTimer - id: user-agent-updates-timer
15:15:38     INFO -  88 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Test timed out.
15:15:39     INFO -  89 INFO TEST-INFO | MEMORY STAT vsize after test: 92483584
15:15:39     INFO -  90 INFO TEST-INFO | MEMORY STAT residentFast after test: 37158912
15:15:39     INFO -  91 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 18803124
15:15:40     INFO -  92 INFO TEST-END | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | finished in 330396ms
15:15:41     INFO -  93 INFO TEST-INFO | dumping last 1 message(s)
15:15:41     INFO -  94 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
15:15:41     INFO -  95 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal): 'onsignalingstatechange' event fired
15:15:41     INFO -  96 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Unexpected event 'onsignalingstatechange' fired with message = 'PeerConnectionWrapper (pcLocal)' at: ["PeerConnectionWrapper/this._pc.onsignalingstatechange@http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1374:5",""]
15:15:41     INFO -  97 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | [SimpleTest.finish()] this test already called finish!
15:15:41     INFO -  98 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | called finish() multiple times
15:15:41     INFO -  99 INFO TEST-INFO | dumping last 1 message(s)
15:15:41     INFO -  100 INFO TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test
15:15:41     INFO -  101 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcRemote): 'onsignalingstatechange' event fired
15:15:41     INFO -  102 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | Unexpected event 'onsignalingstatechange' fired with message = 'PeerConnectionWrapper (pcRemote)' at: ["PeerConnectionWrapper/this._pc.onsignalingstatechange@http://mochi.test:8888/tests/dom/media/tests/mochitest/pc.js:1374:5",""]
15:15:41     INFO -  103 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | [SimpleTest.finish()] this test already called finish!
15:15:41     INFO -  104 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_basicDataOnly.html | called finish() multiple times
15:15:41     INFO -  105 INFO TEST-START | /tests/dom/media/tests/mochitest/test_dataChannel_noOffer.html
15:15:42     INFO -  TEST DEVICES: No test devices found (in media.{audio,video}_loopback_dev, using fake streams.
15:15:43     INFO -  (ice/WARNING) ICE(PC:1401833743680417 (id=19 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_dataChannel_noOffer.html)): No STUN servers specified
15:15:43     INFO -  (ice/NOTICE) ICE(PC:1401833743680417 (id=19 url=http://mochi.test:8888/tests/dom/media/tests/mochitest/test_dataChannel_noOffer.html)): No TURN servers specified
15:15:47     INFO -  106 INFO TEST-INFO | MEMORY STAT vsize after test: 93073408
15:15:47     INFO -  107 INFO TEST-INFO | MEMORY STAT residentFast after test: 37826560
15:15:48     INFO -  108 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 18903488
15:15:48     INFO -  109 INFO TEST-END | /tests/dom/media/tests/mochitest/test_dataChannel_noOffer.html | finished in 6591ms
15:15:49     INFO -  110 INFO TEST-START | /tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio.html
Depends on: 1019923
It should be noted that the code from Bug 1013809 will result in more intermittent test failures like this one. But this is on purpose. Instead of generic test framework timeouts we get now more information why tests did not finished.
And if my gut feeling is right landing of Bug 1017321 will result in this error dis-appearing and instead we will see ICE connection errors, which are the underlying root cause for the majority of our WebRTC intermittent test failures.
https://tbpl.mozilla.org/php/getParsedLog.php?id=41230656&tree=Mozilla-Inbound
Summary: Intermittent test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' | followed by more failures in that file → Intermittent test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' | followed by more failures in that file
Summary: Intermittent test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' | followed by more failures in that file → Intermittent test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' (and more)
https://tbpl.mozilla.org/php/getParsedLog.php?id=41413918&tree=Mozilla-Inbound
Summary: Intermittent test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' (and more) → Intermittent (test_ipc.html) test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' (and more)
https://tbpl.mozilla.org/php/getParsedLog.php?id=41678737&tree=Mozilla-Inbound
Summary: Intermittent (test_ipc.html) test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' (and more) → Intermittent (test_ipc.html) test_dataChannel_basicAudio.html,test_dataChannel_basicDataOnly.html, test_dataChannel_bug1013809.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open' (and more)
I think you're looking at this along with bug 1019923
Assignee: nobody → drno
Yes bug 1019923 could help.
Although this looks more like an ICE error to me. Bug 1022896 should hopefully help here (not sure if the fix has already made it into all the branches here).
I'm going to revisit this if these two fixes don't help.
(In reply to Nils Ohlmeier [:drno] from comment #32)
> Yes bug 1019923 could help.
> Although this looks more like an ICE error to me. Bug 1022896 should
> hopefully help here (not sure if the fix has already made it into all the
> branches here).
> I'm going to revisit this if these two fixes don't help.

Hey Nils, it looks like these fixes haven't helped.  Have you had a chance to relook into this since the other bugs landed last week?
Flags: needinfo?(drno)
The new errors look like we have a few new issues in the test code. I'll try to have a look today or tomorrow.
Flags: needinfo?(drno)
From the recent failures it looks like the wrong order of local_set_remoteDescription before remote_set_localDescription especially on Windows triggers race conditions between checking the status of the data connection and installing the callbacks.
This patch installs the callback handlers first and then check the status. In worst case the callback handler could get called again, but it should not call onSuccess again.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=f6a3750a54c6
Attachment #8448480 - Flags: review?(jib)
(In reply to TBPL Robot from comment #106)
> Tomcat https://tbpl.mozilla.org/php/getParsedLog.php?id=42836265&tree=Mozilla-Inbound
> b2g_emulator_vm mozilla-inbound opt test mochitest-7 on 2014-07-01 00:15:21
> revision: ac9475dcc406
> slave: tst-linux64-spot-1071
> 
> 109 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_bug1013809.html | pc_local: ICE failed to switch to 'connected' state: failed
> 114 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_bug1013809.html | pc_remote: ICE is already in bad state: failed
> 120 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_bug1013809.html | PeerConnectionWrapper (pcLocal) initial dataChannels[0] failed to switch to 'open'
> 127 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_bug1013809.html | PeerConnectionWrapper (pcRemote) initial dataChannels[0] failed to switch to 'open'

I notice in some of these logs, connection failures seem to precede the datachannel failed to open tests. Are we sure there's anything wrong with the datachannel test?
Comment on attachment 8448480 [details] [diff] [review]
bug_1020024_dc_connecting_failures.patch

Review of attachment 8448480 [details] [diff] [review]:
-----------------------------------------------------------------

I don't see a race condition here.

From my understanding of things, state on the peerConnection JS object (as observed from JS[1]) cannot change from one line of JS to the next consecutive line, i.e. for one "run" of JS code back to idle. It is only in things like callbacks that the state of peerConnection (as observed by the JS) has advanced.

I'm reluctant to accept a code-change without a better explanation of how it fixes things, or at least seeing some signs that it does in fact fix things.

[1] = In c++ things are of course multi-threaded, but peerConnection.js updates it state to reflect the underlying system only on the main thread, and this only happens when the event-loop fires, which should only happen when JS is idle (or at the "top" of the calling stack so to speak).

::: dom/media/tests/mochitest/pc.js
@@ +1123,5 @@
>  
>        function dataChannelConnected(channel) {
>          clearTimeout(dcConnectionTimeout);
>          is(channel.readyState, "open", peer + " dataChannels[0] switched to state: 'open'");
> +        if (!dcOpened) {

Can one datachannel be opened more than once?

@@ +1155,3 @@
>        if (onFailure) {
>          dcConnectionTimeout = setTimeout(function () {
> +          const readyState = peer.dataChannels[0].readyState;

Nit: This is an odd use of const to me. Can you point to precedence? I would use var here.
Attachment #8448480 - Flags: review?(jib) → review-
(In reply to Jan-Ivar Bruaroey [:jib] from comment #107)
> I notice in some of these logs, connection failures seem to precede the
> datachannel failed to open tests. Are we sure there's anything wrong with
> the datachannel test?

Sure my patch is not going to do anything about ICE failures. My patch is only about the Windows failures which don't show ICE failures first.
The ICE failures should actually be assertions and the test should stop right there. But that is separate discussion I have with Ted.
(In reply to Jan-Ivar Bruaroey [:jib] from comment #108)
> I don't see a race condition here.
> 
> From my understanding of things, state on the peerConnection JS object (as
> observed from JS[1]) cannot change from one line of JS to the next
> consecutive line, i.e. for one "run" of JS code back to idle. It is only in
> things like callbacks that the state of peerConnection (as observed by the
> JS) has advanced.

Ok. But how can you explain that we get this on Windows platforms:

862 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_dataChannel_bug1013809.html | PeerConnectionWrapper (pcLocal) dataChannels[0] is in state: 'connecting' - got open, expected connecting

If I look at the code:

        if (peer.dataChannels[0].readyState === "open") {
          is(peer.dataChannels[0].readyState, "open", peer + " dataChannels[0] is already in state: 'open'");
          onSuccess();
          return;
        } else {
          is(peer.dataChannels[0].readyState, "connecting", peer + " dataChannels[0] is in state: 'connecting'");
        }

From my reading of that the if condition reads the readState and decides that the state is not "open", that is how we end up in the is() function which expects 'connecting'. But then the is() function claims that when it reads the readyState it in fact is 'open'. So something must have changed the readyState between these two read access to the readyState, or what other explanation do you have? :-)
(In reply to Nils Ohlmeier [:drno] from comment #110)
> Ok. But how can you explain that we get this on Windows platforms:
> 
> 862 INFO TEST-UNEXPECTED-FAIL |
> /tests/dom/media/tests/mochitest/test_dataChannel_bug1013809.html |
> PeerConnectionWrapper (pcLocal) dataChannels[0] is in state: 'connecting' -
> got open, expected connecting
> 
> If I look at the code:
> 
>         if (peer.dataChannels[0].readyState === "open") {
>           is(peer.dataChannels[0].readyState, "open", peer + "
> dataChannels[0] is already in state: 'open'");
>           onSuccess();
>           return;
>         } else {
>           is(peer.dataChannels[0].readyState, "connecting", peer + "
> dataChannels[0] is in state: 'connecting'");
>         }
> 
> From my reading of that the if condition reads the readState and decides
> that the state is not "open", that is how we end up in the is() function
> which expects 'connecting'. But then the is() function claims that when it
> reads the readyState it in fact is 'open'. So something must have changed
> the readyState between these two read access to the readyState, or what
> other explanation do you have? :-)

Ah! You're right and I'm wrong.

What I said is true for all state handled in PeerConnection.js (which used to have a 'readyState' which confused me), but this is on nsDOMDataChannel which is c++ code and gives you the live state (here http://mxr.mozilla.org/mozilla-central/source/netwerk/sctp/datachannel/DataChannel.h#183 )

Sorry about the confusion. I'll change the r- to an r+.

It's food for thought that different parts of the same API has so different side-effects depending on implementation.
Comment on attachment 8448480 [details] [diff] [review]
bug_1020024_dc_connecting_failures.patch

Review of attachment 8448480 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/tests/mochitest/pc.js
@@ +1138,5 @@
>          peer.registerDataChannelOpenEvents(dataChannelConnected);
>        }
>  
> +      if (peer.dataChannels.length >= 1) {
> +        const readyState = peer.dataChannels[0].readyState;

Maybe add a 'snapshot' comment:

const readyState = peer.dataChannels[0].readyState; // snapshot of live value

@@ +1144,5 @@
> +          is(readyState, "open", peer + " dataChannels[0] is already in state: 'open'");
> +          dcOpened = true;
> +          onSuccess();
> +          return;
> +        } else {

Don't need else after return.

@@ +1155,4 @@
>        if (onFailure) {
>          dcConnectionTimeout = setTimeout(function () {
> +          const readyState = peer.dataChannels[0].readyState;
> +          is(readyState, "open", peer + " timed out while waiting for dataChannels[0] to connect");

Actually, you're introducing a bug here: dataChannels[0] is now accessed when peer.dataChannels.length == 0.

I suggest refactoring this to a switch statement on readyState and adding a 'connecting' case, since you only need the setTimeout stuff in that case. That should be easier to follow.
Thanks, added jib's feedback.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=fc78fb0a861e
Attachment #8448480 - Attachment is obsolete: true
Attachment #8449167 - Flags: review?(jib)
Comment on attachment 8449167 [details] [diff] [review]
bug_1020024_dc_connecting_failures.patch

Review of attachment 8449167 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with nits.

::: dom/media/tests/mochitest/pc.js
@@ +1123,4 @@
>  
>        function dataChannelConnected(channel) {
>          clearTimeout(dcConnectionTimeout);
>          is(channel.readyState, "open", peer + " dataChannels[0] switched to state: 'open'");

I would move this down inside if (!dcOpened) so that we don't spam when dcOpened=true.

@@ +1158,5 @@
> +                onFailure();
> +              }, 60000);
> +              break;
> +            }
> +          }

Maybe add a default: case that alarms on closed/closing and calls onFailure() immediately?
Attachment #8449167 - Flags: review?(jib) → review+
Addressed jib's nits.

Carrying forward r+=jib
Attachment #8449167 - Attachment is obsolete: true
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/35e4a142417c
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla33
You need to log in before you can comment on or make changes to this bug.