1041594 - browser_mozAudioChannel_muted.js crashes when run as a directory instead of a full suite

Status: RESOLVED FIXED

(Core :: Web Audio, defect)

Description

[Vaibhav (:vaibhav1994)]

In bug 992911, we are working on running tests per directory, to make the tests less dependent. When we do that, we see that browser_mozAudioChannel_muted.js crashes as can be seen in https://tbpl.mozilla.org/?tree=Try&rev=71ba0eb19adf.

Here's the full log: https://tbpl.mozilla.org/php/getParsedLog.php?id=44149620&tree=Try&full=1

We are planning on switching to this mode of running tests in 2 weeks and would like to do what we can to fix the tests.

Comment 1

[Vaibhav (:vaibhav1994)]

Andrea, could you look at the logs and see what may be causing this problem when we are trying to run tests per directory, i.e., content/media/webaudio/test ?

Comment 2

[Karl Tomlinson (:karlt)]

Thread 0 (crashed)
 0  libsystem_kernel.dylib + 0x12122
    rbx = 0x0000000000065f03   r12 = 0x0000000000065d00
    r13 = 0x0000000000065f03   r14 = 0x00007fff74349200
    r15 = 0x0000000000000000   rip = 0x00007fff87955122
    rsp = 0x00007fff5fbfced8   rbp = 0x00007fff5fbfcf20
    Found by: given as instruction pointer in context
 1  libsystem_c.dylib + 0x19ddc
    rip = 0x00007fff88a3eddd   rsp = 0x00007fff5fbfcee0
    rbp = 0x00007fff5fbfcf20
    Found by: stack scanning
 2  libdyld.dylib + 0x807
    rip = 0x00007fff8a220808   rsp = 0x00007fff5fbfcf00
    rbp = 0x00007fff5fbfcf20
    Found by: stack scanning
 3  libdyld.dylib + 0x817
    rip = 0x00007fff8a220818   rsp = 0x00007fff5fbfcf30
    rbp = 0x00007fff5fbfcf30
    Found by: stack scanning
 4  libdyld.dylib + 0x85a
    rip = 0x00007fff8a22085b   rsp = 0x00007fff5fbfcf60
    Found by: stack scanning
 5  libdyld.dylib + 0x8ed
    rip = 0x00007fff8a2208ee   rsp = 0x00007fff5fbfcff0
    Found by: stack scanning
 6  libmozglue.dylib!arena_purge [jemalloc.c:71ba0eb19adf : 3623 + 0x1a]
    rip = 0x0000000100019eb9   rsp = 0x00007fff5fbfd0d0
    Found by: stack scanning
 7  libmozglue.dylib!arena_run_dalloc [jemalloc.c:71ba0eb19adf : 3759 + 0x9]
    rip = 0x000000010001c135   rsp = 0x00007fff5fbfd130
    Found by: stack scanning
 8  libnss3.dylib!pt_PostNotifies [ptsynch.c:71ba0eb19adf : 106 + 0x8]
    rip = 0x0000000101115d6f   rsp = 0x00007fff5fbfd180
    Found by: stack scanning
 9  libmozglue.dylib!arena_dalloc [jemalloc.c:71ba0eb19adf : 4563 + 0xf]
    rip = 0x0000000100018986   rsp = 0x00007fff5fbfd1d0
    Found by: stack scanning
10  libsystem_c.dylib + 0x2d8c7
    rip = 0x00007fff88a528c8   rsp = 0x00007fff5fbfd220
    Found by: stack scanning
11  XUL!js::LifoAlloc::freeAll() [Utility.h:71ba0eb19adf : 122 + 0x4]
    rip = 0x00000001039fe117   rsp = 0x00007fff5fbfd270
    Found by: stack scanning
12  XUL!js::gc::StoreBuffer::enable() [StoreBuffer.h:71ba0eb19adf : 191 + 0x7]
    rip = 0x0000000103a43231   rsp = 0x00007fff5fbfd290
    Found by: stack scanning
13  XUL!js::gc::GCRuntime::gcCycle(bool, long long, js::JSGCInvocationKind, JS::gcreason::Reason) [jsgc.cpp:71ba0eb19adf : 5030 + 0x8]
    rip = 0x0000000103cacd9f   rsp = 0x00007fff5fbfd2c0
    Found by: stack scanning
14  XUL!js::gc::GCRuntime::collect(bool, long long, js::JSGCInvocationKind, JS::gcreason::Reason) [jsgc.cpp:71ba0eb19adf : 5234 + 0x14]
    rip = 0x0000000103cad063   rsp = 0x00007fff5fbfd320
    Found by: stack scanning
15  XUL!PreciseGCRunnable::Run() [XPCComponents.cpp:71ba0eb19adf : 2889 + 0xc]
    rip = 0x000000010249f824   rsp = 0x00007fff5fbfd380
    Found by: stack scanning
16  XUL!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:71ba0eb19adf : 766 + 0x5]
    rip = 0x000000010142d024   rsp = 0x00007fff5fbfd3b0
    Found by: stack scanning

Comment 3

[Andrea Marchesini [:baku]]

Sorry for the delay. Is this issue still reproducible?
The try result is not valid anymore, if you have something up-to-date I can take a look.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

I pushed this last night- the error is on osx opt only which I thought over night I would see results, here is a try push:
https://tbpl.mozilla.org/?tree=Try&rev=8194c614db4b

I am still awaiting osx opt results as of writing this comment, but we will see.

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

this happens on 10.8, here is a link to the log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=46450747&tree=Try

:baku, thanks for looking into this!

Comment 6

[Andrea Marchesini [:baku]]

It's hard to say what is going on here. I need more information:

1. not all the messages printed by the test appear. browser_mozAudioChannel.js and browser_mozAudioChannel_muted.js had several tests, but nothing is printed. Do you know why and how to show them?

2. how can I reproduce this new configuration locally? Usually I run mochitests individually or per directory using |moch mochitest-something path|.

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

I am not sure why the full output is not being printed :(  I have only modified a few manifests, not tests or the browser.

I assume you could run this locally on osx opt builds like so:
mach mochitest-browser content/media/webaudio/test

I have found that running locally it is hard to reproduce problems seen on try server.

Comment 8

[Karl Tomlinson (:karlt)]

(In reply to Andrea Marchesini (:baku) from comment #6)
> 1. not all the messages printed by the test appear.
> browser_mozAudioChannel.js and browser_mozAudioChannel_muted.js had several
> tests, but nothing is printed. Do you know why and how to show them?

Sounds like bug 974073, perhaps?

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

:baku, any luck with this bug?

Comment 10

[Andrea Marchesini [:baku]]

Attachment: test.patch

I don't have mac, and I cannot reproduce the issue. I would like to know if you can apply this patch and push it to try. Or tell me how to have a push to try that enables the feature you are working on. Thanks.

This patch adds debugging messages.

Comment 11

[Joel Maher ( :jmaher ) (UTC -8)]

I have pushed to try:
https://tbpl.mozilla.org/?tree=Try&rev=82f183077a7e

When I test out runbydir, I add this in my patch queue:
https://hg.mozilla.org/try/diff/0b5eb184c71d/testing/mochitest/runtests.py

Comment 12

[Joel Maher ( :jmaher ) (UTC -8)]

I ran this on try with 3 jobs:
https://tbpl.mozilla.org/?tree=Try&rev=82f183077a7e

the oranges are for another failure and I investigated the logs to ensure that mozAudioChannel_muted.js was run successfully!

I say lets move forward with this patch to get it landed!

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

oh, I lied, the 4th run finished:
https://tbpl.mozilla.org/php/getParsedLog.php?id=46567953&tree=Try&full=1#error4

we get a timed out error, maybe the logs have more useful information?

Comment 14

[Joel Maher ( :jmaher ) (UTC -8)]

Hi :baku, it is a new week!  Do you have other thoughts?  I would be more than happy to push stuff to try or help out.

Comment 15

[Andrea Marchesini [:baku]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=46567953&tree=Try&full=1#error4
in this there are not my debug messages. are you sure you pushed my patch? They should be visible. It least I see them locally.
Unfortunately I cannot use karlt suggested in bug 8 because it seems that forceCompleteLog()/requireCompleteLog() do not exist for browser mochitests.

Comment 16

[Joel Maher ( :jmaher ) (UTC -8)]

I am looking into why the patch isn't printing out lines- stay tuned!

Comment 17

[Joel Maher ( :jmaher ) (UTC -8)]

I have the data printed out (the scripts we run in automation add a --quiet flag, I have removed that in my patch queue):
https://tbpl.mozilla.org/?tree=Try&rev=3a9bb1220a13

of course with all these retriggers I have no failures :(

Could this be a timing issue where adding the logging has prevented us from seeing this crash due to increased IO or other timing/cleanup?

Comment 18

[Andrea Marchesini [:baku]]

> Could this be a timing issue where adding the logging has prevented us from
> seeing this crash due to increased IO or other timing/cleanup?

Actually yes. The timing is an important factor in these tests. Let me work on it.

Comment 19

[Joel Maher ( :jmaher ) (UTC -8)]

awesome, thanks!

Comment 20

[Joel Maher ( :jmaher ) (UTC -8)]

I am having a hard time reproducing this now:
https://tbpl.mozilla.org/?tree=Try&rev=9d52c5041087

At first I thought my hacks to print out all the information were causing this to pass, but the linked in try push above shows all green.

:baku, did you find out anything?  Should we consider closing this?

Comment 21

[Andrea Marchesini [:baku]]

> :baku, did you find out anything?  Should we consider closing this?

I don't believe in bugs able to fix themselves :) But I didn't fine anything actually. I tried to rotate the test, but in the end the test seems correct: I didn't find any obvious timing issues.

Maybe we can close this bug and open it in case this issue reappears.

Comment 22

[Ryan VanderMeulen [:RyanVM]]

My concern with doing that is that bugs like these tend to come back at random times, which only leads to tree closures, backouts, etc down the road. Do I need to remind you about the pain we were going through with random devtools test additions causing perma-orange because they happened to shift a test into a different chunk than before? Those are the worst kind of issues to sheriff and they cause massive developer frustration.

Closing this bug and keeping our fingers crossed seems like taking the easy way out here and I strongly suspect it'll come back to bite us in the butt later if we do.

Comment 23

[Ryan VanderMeulen [:RyanVM]]

I think the best thing we can do right now is try to bisect down to what changeset made this go away. Who knows, it could be a legitimate code fix :). But before we wash our hands of this, I think we need to understand whether it was random perturbation that made it go or something legitimate.

Comment 24

[Ryan VanderMeulen [:RyanVM]]

I'm actually wondering if this got fixed by the MediaStreamGraph refactor (bug 848954). Might be a good before/after for bisecting.

Comment 25

[Joel Maher ( :jmaher ) (UTC -8)]

before: https://tbpl.mozilla.org/?tree=Try&rev=60c8f8511568
after: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=41ecdecf96fb

In a few hours we will have results for that data point.

Comment 26

[Andrew Overholt [:overholt]]

(In reply to Joel Maher (:jmaher) from comment #25)
> before: https://tbpl.mozilla.org/?tree=Try&rev=60c8f8511568
> after:
> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=41ecdecf96fb

So bug 848954 didn't fix it?

Comment 27

[Joel Maher ( :jmaher ) (UTC -8)]

in 8 data points I have 2 failures:
https://tbpl.mozilla.org/?tree=Try&rev=eb6f0b691200&jobname=.*MacOSX.*%20test%20mochitest-browser-chrome-2

There is one other failure in e10s tests, so it might take a week or so to get this going again.  Can you take a look at the above try push and see if anything stands out as a problem?

Comment 28

[Andrea Marchesini [:baku]]

I suspected that patch for bug 1075345 fixes this issue.

Comment 29

[Andrea Marchesini [:baku]]

Attachment: test.patch

Ehsan, can you review this patch? The reason why we have this failure is that StartPlaying() in AudioChannelNode is called asynchronously. In the meantime it could be that another AudioChannel object starts playing, creating a race condition.

Comment 30

[Andrea Marchesini [:baku]]

Attachment: test.patch

Comment 31

[(no longer active)]

Comment on attachment 8504733 [details] [diff] [review]
test.patch

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

The code changes look fine, but I don't think this is the right way to fix the tests, as described below.

::: content/media/webaudio/test/browser_mozAudioChannel.html
@@ +37,5 @@
>    source.connect(ac.destination);
>    source.loop = true;
>    source.start(0);
> +
> +  document.getElementById("mozAudioChannelTest").innerHTML = "READY";

I'm not sure how this helps.  The load event must be dispatched after this script runs before your patch anyway.

::: content/media/webaudio/test/browser_mozAudioChannel.js
@@ +20,5 @@
>  
> +function waitForReady(doc, aCallback) {
> +  var e = doc.getElementById("mozAudioChannelTest");
> +  if (!e || e.innerHTML != 'READY') {
> +    setTimeout(function() { waitForReady(doc, aCallback); }, 500);

Can't you wait for the load event and avoid the polling here?

@@ -78,5 @@
> -
> -            info("Restoring the tab...");
> -            whenTabRestored(tab2, function() { info("Tab restored."); });
> -          }
> -        );

I'm assuming this is just indentation changes.

::: content/media/webaudio/test/browser_mozAudioChannel_muted.html
@@ +21,5 @@
>      document.getElementById("mozAudioChannelTest").innerHTML = "mozinterruptend";
>    }, false);
>  
>    document.getElementById("mozAudioChannelTest").innerHTML = "READY";
> +}

This change is also unneeded, I think.

::: content/media/webaudio/test/browser_mozAudioChannel_muted.js
@@ +29,5 @@
>  
> +function waitForReady(doc, aCallback) {
> +  var e = doc.getElementById("mozAudioChannelTest");
> +  if (!e || e.innerHTML != 'READY') {
> +    setTimeout(function() { waitForReady(doc, aCallback); }, 500);

Ditto.

@@ -63,5 @@
> -              gBrowser.removeTab(tab2);
> -              gBrowser.selectedTab = tab1;
> -            });
> -          }
> -        );

Again I'm assuming this is an indentation change.

Comment 32

[Andrea Marchesini [:baku]]

Attachment: test.patch

So the main issue here is when do we consider the AudioContext playing audio.
To me the audiocontext starts playing audio immediately, before the first block and this patch implements this concept.

Comment 33

[Andrea Marchesini [:baku]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/09e514e23ef1

Comment 35

[Andrea Marchesini [:baku]]

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=b83226f8040f

Comment 36

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/09e514e23ef1