853858 - Intermittent test_peerConnection_basicAudio.html, test_peerConnection_basicAudioVideo.html, test_peerConnection_basicAudioVideoCombined.html, test_peerConnection_basicVideo.html, test_peerConnection_bug827843.html, test_peerConnection_bug | Test timed out

Status: RESOLVED FIXED

(Core :: WebRTC: Signaling, defect, P1)

Description

[Adam Roach [:abr]]

+++ This bug was initially created as a clone of Bug #839677 +++

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=20886816&tree=Mozilla-Inbound
Ubuntu 12.04 x64 mozilla-inbound opt test mochitest-2 on 2013-03-20 08:43:11
slave: tst-linux64-ec2-324

09:06:53     INFO -  26689 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Test timed out.

Comment 1

[Legacy TBPL/Treeherder Robot]

jesup
https://tbpl.mozilla.org/php/getParsedLog.php?id=20999988&tree=Try
Rev4 MacOSX Lion 10.7 try debug test mochitest-2 on 2013-03-22 18:10:16
slave: talos-r4-lion-019

18:43:37     INFO -  26496 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Test timed out.

Comment 2

[Adam Roach [:abr]]

Attachment: Additional instrumentation for on-hook event

Comment 3

[Adam Roach [:abr]]

Comment on attachment 729798 [details] [diff] [review]
Additional instrumentation for on-hook event

This bug is one of a class of bug where a call is torn down with an ONHOOK event, but no corresponding messaging happens towards the PeerConnection. Since no callback is issued, the corresponding tests time out.

This patch does three things to help shed some light on why calls are sometimes town down without sending an event back to the PeerConnection. (1) All calls to cc_onhook and friends now indicate the source file and line number from which it was called; (2) PeerConnectionImpl has additional logging messages that are printed when it is about to invoke endCall (which ultimately causes an ONHOOK event to be triggered); and (3) Logging of messages sent to the "ui" (PeerConnectionImpl) has been increased from Debug to Notice so that it will be emitted during mochi tests.

Comment 4

[Ethan Hugg [:ehugg]]

Comment on attachment 729798 [details] [diff] [review]
Additional instrumentation for on-hook event

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

::: media/webrtc/signaling/src/sipcc/core/gsm/ccapi.c
@@ +1422,5 @@
>      pmsg->active_list  = active_list;
>  
>      CC_DEBUG_ENTRY(__FUNCTION__, src_id, dst_id, call_id, line, cc_msg_name(pmsg->msg_id));
> +    DEF_DEBUG("(%d/%d) On-hook called from %s:%d",
> +              line, call_id, filename, fileline);

Nit: I believe both line_t and callid_t are unsigned.

::: media/webrtc/signaling/src/sipcc/core/includes/phone_debug.h
@@ +108,5 @@
>  #define PHN_DEBUG_SNTP_PACKET if (DebugSNTPPacket)
>  
>  /* TNP adapter debugs */
>  #define TNP_DEBUG(format,...) if (TNPDebug) \
> +        CSFLogNotice("tnp", format, ## __VA_ARGS__)

You may want to mention here why you are redirecting debug to notice.

Comment 5

[Adam Roach [:abr]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/817fd65ab44b

Comment 6

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/817fd65ab44b

Comment 7

[Adam Roach [:abr]]

Okay, I think I see what's going on here, thanks to the log in Bug 854255 comment 7. The telltale clue is that things are cruising along just fine and then *BAM* out of left field, someone destroys the PC.

How can this happen? Well, the PC is rooted in the content javascript context. By my understanding, the only way it can be destroyed is by the content javascript relinquishing all references to it. Once that happens, the garbage collector will eventually find it and clean it up.

Turning to the test at hand; the mochitest itself starts the chain of events like this:

  runTest(function () {
    var test = new PeerConnectionTest();
    test.setMediaConstraints([{audio: true}, {video: true}],
                             [{audio: true}, {video: true}]);
    test.run();
  }, true);

That "PeerConnectionTest" object contains the two PCs that will be used for the test.

Now, keep in mind that the "test.run()" function call only executes the first step in the chain of events and then returns. And then the runTest() function returns. And the "test" variable goes out of scope.

That last step is critical: once the "test" variable goes out of scope, the entire graph of objects comprising PeerConnectionTest, its two PCs, their observers, and their supporting C++ objects becomes unrooted, and subject to collection the next time the garbage collector runs.

If that happens before the test is finished, then your PCs go away (along with all your testing objects), and no more callbacks get fired.

The following test cases all reuse this pattern, and will consequently share this pathology:

* test_peerConnection_basicAudio.html (this bug)
* test_peerConnection_basicAudioVideo.html (Bug 854255)
* test_peerConnection_basicAudioVideoCombined.html (Bug 845538)
* test_peerConnection_basicVideo.html
* test_peerConnection_bug827843.html
* test_peerConnection_bug840344.html (Bug 841496)

I'm duping those other bugs to this one, and renaming this one so it will match in tbpl for star purposes.

I think the solution is to move the "var test = new PeerConnectionTest();" into a global scope so it survives for the duration of the test. I'll attach a patch shortly.

Comment 11

[Adam Roach [:abr]]

Attachment: Move PeerConnectionTest instance reference into global scope

Comment 12

[Adam Roach [:abr]]

This patch is untested -- I'm waiting for a tree clobber to finish so I can give it a try.

Comment 13

[Adam Roach [:abr]]

Comment on attachment 733333 [details] [diff] [review]
Move PeerConnectionTest instance reference into global scope

This works locally, although I've never been able to replicate the timeout on a local machine (so I can't verify that the problem is gone)...

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 733333 [details] [diff] [review]
Move PeerConnectionTest instance reference into global scope

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

Go for it!

Comment 15

[Adam Roach [:abr]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8daa66c443a3

Comment 16

[Matt Brubeck (:mbrubeck)]

Sorry, backed this out because it's failing on Android and B2G:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b76be1ee5350

Comment 17

[Jason Smith [:jsmith]]

Ah, I know why this failed. In global scope, we don't do the user agent checking, so this is always going to fail on alternative platforms right now.

A simple fix to this problem I think would be to define the var in global scope, but only create the object within the runTest object.

Comment 18

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Move PeerConnectionTest instance reference into global scope

Comment 19

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 733756 [details] [diff] [review]
Move PeerConnectionTest instance reference into global scope

Either one should do for this sort of bustage fix

https://tbpl.mozilla.org/?tree=Try&rev=257ff0591dc6
(Oranges are not us; mostly infra)

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 733756 [details] [diff] [review]
Move PeerConnectionTest instance reference into global scope

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

Yay for complicate dependencies. This looks fine now and should also pass on Android.

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+2]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/fddde2d1e9b2

Comment 22

[Ryan VanderMeulen [:RyanVM]]

Backed out for leaking the world on Windows mochitest-2.
https://hg.mozilla.org/integration/mozilla-inbound/rev/f7156b703f3d

https://tbpl.mozilla.org/php/getParsedLog.php?id=21469097&tree=Mozilla-Inbound

The tbpl leak analyzer says 10 DOMWINDOWS leaked.

Comment 23

[Jason Smith [:jsmith]]

Well, so much for my idea for working around this problem. We fix the platform issue and now we have leaks.

Clint - Why is mochitest blowing up here with the global reference we are doing in this patch?

Comment 24

[Randell Jesup [:jesup] (needinfo me)]

I looked into it in detail this morning and chatted with Ryan.  This really, really looks like some other random orange - the log is full of no-window and out-of-memory errors that don't seem connected to our code while trying to shut down (and that may be why cleanup didn't happen for a ton of stuff).  There's no way moving the scope of this JS var caused this, and all the pushes between this and the backout were green as well (or other known oranges).

I'm going to ask Ryan to let me re-land it (we'd discussed that I would likely do so earlier).

Comment 25

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8262a337d5be

The leaks occurred in Win7 M2, and the logs show none of the tests in this patch ran in M2.  Relanded.

Comment 26

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/8262a337d5be

Comment 27

[Randell Jesup [:jesup] (needinfo me)]

Comment on attachment 733756 [details] [diff] [review]
Move PeerConnectionTest instance reference into global scope

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Initial test

User impact if declined: Random oranges in tests - this patch just updates the tests to make them not sensitive to GC.

Testing completed (on m-c, etc.): Just landed on m-c.

Risk to taking this patch (and alternatives if risky): minimal to no risk and the risk is only to tests run on 22 in automation.

String or IDL/UUID changes made by this patch:

Comment 28

[Alex Keybl [:akeybl]]

Comment on attachment 733756 [details] [diff] [review]
Move PeerConnectionTest instance reference into global scope

Basically NPOTB, and fixes orange. a+

Comment 29

[Randell Jesup [:jesup] (needinfo me)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b304eeae475b

Comment 30

[Legacy TBPL/Treeherder Robot]

jfkthame
https://tbpl.mozilla.org/php/getParsedLog.php?id=21634469&tree=Mozilla-Beta
Rev4 MacOSX Lion 10.7 mozilla-beta opt test mochitest-3 on 2013-04-09 19:09:50
slave: talos-r4-lion-015

297 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Test timed out.

Comment 31

[Maire Reavy [:mreavy]]

Per comment 29, removing webrtc-uplift flag

Comment 33

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=23108970&tree=Mozilla-Aurora
Android Tegra 250 mozilla-aurora opt test mochitest-4 on 2013-05-18 02:21:56
slave: tegra-039

9758 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html | Test timed out.
9766 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Test timed out.
05-18 02:47:10.630 I/GeckoDump( 1798): 9766 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Test timed out.