Closed Bug 965656 Opened 6 years ago Closed 6 years ago

Intermittent test_peerConnection_bug834153.html | Test timed out.

Categories

(Core :: WebRTC, defect, P1)

All
Gonk (Firefox OS)
defect

Tracking

()

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

People

(Reporter: KWierso, Assigned: drno)

References

Details

(Keywords: intermittent-failure)

Attachments

(4 files, 6 obsolete files)

https://tbpl.mozilla.org/php/getParsedLog.php?id=33777586&tree=Mozilla-Inbound
slave: tst-linux64-spot-406



18:10:18     INFO -  17677 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Spec and MapClass variant of RTCStatsReport enumeration agree
18:10:18     INFO -  17678 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Have at least 1 inboundrtp stat(s) *
18:10:18     INFO -  17679 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Have 1 outboundrtp stat(s)
18:10:18     INFO -  17680 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Have localcandidate stat(s)
18:10:18     INFO -  17681 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Have remotecandidate stat(s)
18:10:18     INFO -  17682 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Closing peer connections. Connection state=false
18:10:18     INFO -  17683 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | iceConnectionState should not be undefined
18:10:18     INFO -  17684 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | PeerConnectionWrapper (pcLocal): oniceconnectionstatechange fired, new state is: closed
18:10:18     INFO -  17685 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | PeerConnectionWrapper (pcLocal): Closed connection.
18:10:18     INFO -  17686 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | iceConnectionState should not be undefined
18:10:18     INFO -  17687 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | PeerConnectionWrapper (pcRemote): oniceconnectionstatechange fired, new state is: closed
18:10:18     INFO -  17688 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | PeerConnectionWrapper (pcRemote): Closed connection.
18:17:00     INFO -  17689 INFO TEST-INFO | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Test finished
18:17:00     INFO -  17690 INFO TEST-INFO | MEMORY STAT vsize after test: 118722560
18:17:00     INFO -  17691 INFO TEST-INFO | MEMORY STAT residentFast after test: 55169024
18:17:00     INFO -  17692 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 24179420
18:17:00     INFO -  17693 INFO TEST-END | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | finished in 46874ms
18:17:00     INFO -  17694 INFO TEST-START | /tests/dom/media/tests/mochitest/test_peerConnection_bug822674.html
18:17:00     INFO -  17695 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug822674.html | Can set expandos on an RTCPeerConnection
18:17:00     INFO -  17696 INFO TEST-INFO | MEMORY STAT vsize after test: 116690944
18:17:00     INFO -  17697 INFO TEST-INFO | MEMORY STAT residentFast after test: 54067200
18:17:00     INFO -  17698 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 21902256
18:17:00     INFO -  17699 INFO TEST-END | /tests/dom/media/tests/mochitest/test_peerConnection_bug822674.html | finished in 9610ms
18:17:00     INFO -  17700 INFO TEST-START | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html
18:17:00     INFO -  17701 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection() succeeds
18:17:00     INFO -  17702 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection(1) throws
18:17:00     INFO -  17703 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({}) succeeds
18:17:00     INFO -  17704 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({"iceServers":[]}) succeeds
18:17:00     INFO -  17705 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({"iceServers":[{"url":""}]}) throws
18:17:00     INFO -  17706 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({"iceServers":[{"url":"stun:127.0.0.1"},{"url":"stuns:localhost","foo":""},{"url":"turn:[::1]:3478","username":"p","credential":"p"},{"url":"turns:localhost:3478?transport=udp","username":"p","credential":"p"}]}) succeeds
18:17:00     INFO -  17707 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({"iceServers":[{"url":"turns:localhost:3478","username":"p"}]}) throws
18:17:00     INFO -  17708 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({"iceServers":[{"url":"turns:localhost:3478","credential":"p"}]}) throws
18:17:00     INFO -  17709 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection({"iceServers":[{"url":"http:0.0.0.0"}]}) throws
18:17:00     INFO -  17710 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | mozRTCPeerConnection() constructor has readable exceptions
18:17:00     INFO -  17711 INFO TEST-INFO | MEMORY STAT vsize after test: 118788096
18:17:00     INFO -  17712 INFO TEST-INFO | MEMORY STAT residentFast after test: 54284288
18:17:00     INFO -  17713 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 22659964
18:17:00     INFO -  17714 INFO TEST-END | /tests/dom/media/tests/mochitest/test_peerConnection_bug825703.html | finished in 34428ms
18:17:00     INFO -  17715 INFO TEST-START | /tests/dom/media/tests/mochitest/test_peerConnection_bug834153.html
18:17:00     INFO -  17716 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug834153.html | Test timed out.
18:17:00     INFO -  17717 INFO TEST-INFO | MEMORY STAT vsize after test: 114528256
18:17:00     INFO -  17718 INFO TEST-INFO | MEMORY STAT residentFast after test: 51224576
18:17:00     INFO -  17719 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 20129452
18:17:00     INFO -  17720 INFO TEST-END | /tests/dom/media/tests/mochitest/test_peerConnection_bug834153.html | finished in 330145ms
18:17:00     INFO -  17721 INFO TEST-START | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html
18:17:00     INFO -  17722 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed) succeeds
18:17:00     INFO -  17723 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, 1) throws
18:17:00     INFO -  17724 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, {}) succeeds
18:17:26     INFO -  17725 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer has readable exceptions
18:17:26     INFO -  17726 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, { mandatory: { FooBar: true } }) throws
18:17:26     INFO -  17727 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, { optional: [] }) succeeds
18:17:26     INFO -  17728 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, { optional: [1] }) throws
18:17:26     INFO -  17729 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, { optional: [{ OfferToReceiveVideo: false, OfferToReceiveAudio: true, }] }) throws
18:17:26     INFO -  17730 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_peerConnection_bug835370.html | createOffer(step1, failed, { mandatory: { OfferToReceiveVideo: false, OfferToReceiveAudio: true, MozDontOfferDataChannel: true}, optional: [{ VoiceActivityDetection: true }, { FooBar: "42"  }] }) succeeds
18:17:26     INFO -  17731 INFO TEST-INFO | MEMORY STAT vsize after test: 114528256
18:17:26     INFO -  17732 INFO TEST-INFO | MEMORY STAT residentFast after test: 52178944
18:17:26     INFO -  17733 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 20931988
Adam, this is currently the #8 top orange on trunk. Can you please look into this?
Flags: needinfo?(adam)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #103)
> Adam, this is currently the #8 top orange on trunk. Can you please look into
> this?

I'm not going to have any cycles to look at this. I spoke to Maire, and she's going to find someone to assign it to. Lateralling the "needinfo" to her...
Flags: needinfo?(adam) → needinfo?(mreavy)
I'm concerned that the test (at least in #102) according to their logging show overlapping network activity from tests which are finished already.

Here is proposed action plan:
#1 make sure we call close() on the PC objects in these tests to have them stop network activity.
#2 if #1 does not help try to call the garbage collector explicitly at the end of each of these tests in the attempt to shut down the PC objects sooner.
Assignee: nobody → drno
Flags: needinfo?(mreavy)
Attachment #8400871 - Flags: review?(rjesup) → review+
I removed the test case from the patch which caused the failures.
Carrying forward the r+=jesup.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=3d028fb15e49
Attachment #8400871 - Attachment is obsolete: true
Keywords: checkin-needed
So obviously action #1 did not helped. But rather then trying to mess with garbage collector my new plan is to get Bug 989936 fixed, which would allow tests to wait for PC's to be closed before moving on. I would hope this should help us with this one here.
(In reply to Nils Ohlmeier [:drno] from comment #140)
> So obviously action #1 did not helped. But rather then trying to mess with
> garbage collector my new plan is to get Bug 989936 fixed, which would allow
> tests to wait for PC's to be closed before moving on. I would hope this
> should help us with this one here.

This intermittent failure is #7 on OrangeFactor, and as such worthy of escalation due to https://wiki.mozilla.org/Sheriffing/Test_Disabling_Policy

Do you have a rough estimate for timeframe for the bug 989936? :-)
Depends on: 989936
Flags: needinfo?(drno)
(In reply to Ed Morley (Away until 6th May) [:edmorley UTC+0] from comment #242)
> Do you have a rough estimate for timeframe for the bug 989936? :-)

Thanks for the reminder. I'll try to add something within the next 2-3 days.
Flags: needinfo?(drno)
Getting everything closed in all our tests is more complicated then I expected. Lets get this done in several patches.
This first patch calls close() on all PC's in the PC specific tests.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=ab5777087020
Attachment #8421078 - Flags: review?(rjesup)
Attachment #8421078 - Flags: review?(rjesup) → review+
See Also: → 1009124
Attachment #8401456 - Flags: checkin+
Attachment #8421078 - Flags: checkin?
Attachment #8401456 - Flags: checkin+ → checkin-
Attachment #8421078 - Flags: checkin? → checkin+
Not sure if I'm using the checkin+/- flags correctly here: I would like to get the  wait_for_close_in_tests.patch checked in.
The "Adding missing close() calls to two tests (without test case)" patch is landed already.
Keywords: checkin-needed
Attached patch close_datachannel.patch (obsolete) — Splinter Review
This patch goes through all open data channels and closes any remaining open data channel (if needed from both sides). It also adds an overall timeout in case the closing does not work to prevent a test framework timeout.
It also tries to prepare for running the same test case on two separate machines with steeplechase, although this has not been tested.
Attachment #8422892 - Flags: review?(rjesup)
Comment on attachment 8422892 [details] [diff] [review]
close_datachannel.patch

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

::: dom/media/tests/mochitest/pc.js
@@ +547,5 @@
>        self.waitingForRemote = true;
>        self.pcRemote.close();
>      }
> +    // give the signals handlers time to fire
> +    setTimeout(verifyClosed, 100);

Very concerned about such a "short" timeout when we have to run on b2g emulators, etc.  In general, most "wait for event" timeouts should be LONG (within a factor of say 2 or 3 of the overall mochitest timeout time; if they fail taking a long time to fail (and orange) is ok)

@@ +822,5 @@
> +        _closePeerConnection();
> +      }
> +      else {
> +        closeTimeout = setTimeout(function() {
> +          ok(false, "Failed to properly close data channels: " + 

trailing space

@@ +918,5 @@
> +            verifyClosedChannels();
> +          };
> +
> +          // we both channels available so wait for the remote even by default
> +          // apparently this is need for Linux debug builds?!?

Rewrite comment; confusing.
Is there a bug on Linux debug builds?  Bug # should be here if so.  If there is a bug but it isn't filed; file and include STR and pointers to Try/etc logs

@@ +1834,1 @@
>          clearTimeout(self.addStreamTimeout);

Yup, that looks like it was a bug!
Attachment #8422892 - Flags: review?(rjesup) → review+
Summary: Intermittent TEST-UNEXPECTED-FAIL | test_peerConnection_bug834153.html | Test timed out. → Intermittent test_peerConnection_bug834153.html | Test timed out.