Closed Bug 1447180 Opened 2 years ago Closed 2 years ago

Intermittent browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | recording-device-events notification unexpected - Got 1, expected 0

Categories

(Core :: WebRTC, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla61
Tracking Status
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: arai)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:timing])

Attachments

(1 file, 2 obsolete files)

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=169071642&repo=mozilla-central

https://queue.taskcluster.net/v1/task/E72fN1S3QTSgx_xgW1-WXA/runs/0/artifacts/public/logs/live_backing.log

[task 2018-03-19T23:36:28.665Z] 23:36:28     INFO - requesting devices
[task 2018-03-19T23:36:28.666Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | webRTC-shareDevices notification shown - 
[task 2018-03-19T23:36:28.667Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | notification panel open - 
[task 2018-03-19T23:36:28.668Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | notification panel populated - 
[task 2018-03-19T23:36:28.668Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | expected notification getUserMedia:request - 
[task 2018-03-19T23:36:28.669Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | anchored to device icon - 
[task 2018-03-19T23:36:28.669Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | microphone selector hidden - 
[task 2018-03-19T23:36:28.670Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | camera selector hidden - 
[task 2018-03-19T23:36:28.671Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | screen selector visible - 
[task 2018-03-19T23:36:28.671Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | received ok - 
[task 2018-03-19T23:36:28.671Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | expected notification getUserMedia:response:allow - 
[task 2018-03-19T23:36:28.672Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | expected notification recording-device-events - 
[task 2018-03-19T23:36:28.672Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | sharing attribute is set - 
[task 2018-03-19T23:36:28.673Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | showing screen icon in the identity block - 
[task 2018-03-19T23:36:28.673Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | sharing icon(s) should be in paused state when paused - 
[task 2018-03-19T23:36:28.674Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | sharing state for microphone as expected - 
[task 2018-03-19T23:36:28.675Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | should not show microphone icon in the control center panel - 
[task 2018-03-19T23:36:28.675Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | sharing state for camera as expected - 
[task 2018-03-19T23:36:28.676Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | should not show camera icon in the control center panel - 
[task 2018-03-19T23:36:28.677Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | sharing state for screen as expected - 
[task 2018-03-19T23:36:28.678Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | should show screen icon in control center panel - 
[task 2018-03-19T23:36:28.679Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | icon should have the in-use class, unless paused - 
[task 2018-03-19T23:36:28.679Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | WebRTC indicator visible - 
[task 2018-03-19T23:36:28.680Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | camera global indicator as expected - 
[task 2018-03-19T23:36:28.681Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | microphone global indicator as expected - 
[task 2018-03-19T23:36:28.682Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | screen global indicator as expected - 
[task 2018-03-19T23:36:28.682Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | WebRTC menu should be visible - 
[task 2018-03-19T23:36:28.683Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | popup WebRTC indicator visible - 
[task 2018-03-19T23:36:28.684Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | video global indicator attribute as expected - 
[task 2018-03-19T23:36:28.685Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | audio global indicator attribute as expected - 
[task 2018-03-19T23:36:28.686Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | screen global indicator attribute as expected - 
[task 2018-03-19T23:36:28.686Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | only one global indicator window - 
[task 2018-03-19T23:36:28.688Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | webrtcUI wants the global indicator shown - 
[task 2018-03-19T23:36:28.688Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | webrtcUI wants the screen sharing indicator shown - 
[task 2018-03-19T23:36:28.689Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | webrtcUI wants the camera indicator hidden - 
[task 2018-03-19T23:36:28.690Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | webrtcUI wants the mic indicator hidden - 
[task 2018-03-19T23:36:28.690Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | 2 active desktop sharing streams - 
[task 2018-03-19T23:36:28.691Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | 2 active streams - 
[task 2018-03-19T23:36:28.695Z] 23:36:28     INFO - removing the second tab
[task 2018-03-19T23:36:28.695Z] 23:36:28     INFO - Buffered messages finished
[task 2018-03-19T23:36:28.696Z] 23:36:28     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | recording-device-events notification unexpected - Got 1, expected 0
[task 2018-03-19T23:36:28.696Z] 23:36:28     INFO - Stack trace:
[task 2018-03-19T23:36:28.696Z] 23:36:28     INFO - chrome://mochikit/content/browser-test.js:test_is:1283
[task 2018-03-19T23:36:28.696Z] 23:36:28     INFO - chrome://mochitests/content/browser/browser/base/content/test/webrtc/head.js:listener:228
[task 2018-03-19T23:36:28.697Z] 23:36:28     INFO - closing the stream
[task 2018-03-19T23:36:28.697Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | got recording-device-events notification - 
[task 2018-03-19T23:36:28.697Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | got recording-window-ended notification - 
[task 2018-03-19T23:36:28.698Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | WebRTC indicator hidden - 
[task 2018-03-19T23:36:28.698Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | camera global indicator as expected - 
[task 2018-03-19T23:36:28.698Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | microphone global indicator as expected - 
[task 2018-03-19T23:36:28.699Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | screen global indicator as expected - 
[task 2018-03-19T23:36:28.699Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | WebRTC menu should be hidden - 
[task 2018-03-19T23:36:28.699Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | popup WebRTC indicator hidden - 
[task 2018-03-19T23:36:28.700Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | webrtcUI wants the global indicator hidden - 
[task 2018-03-19T23:36:28.700Z] 23:36:28     INFO - TEST-PASS | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | 0 active streams - 
[task 2018-03-19T23:36:28.700Z] 23:36:28     INFO - Leaving test bound test
[task 2018-03-19T23:36:28.701Z] 23:36:28     INFO - GECKO(1935) | Collecting coverage for: chrome://mochitests/content/browser/browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js
[task 2018-03-19T23:36:29.207Z] 23:36:29     INFO - GECKO(1935) | Writing coverage to: /builds/worker/workspace/build/blobber_upload_dir/jscov_1521502589202.json
[task 2018-03-19T23:36:29.249Z] 23:36:29     INFO - GECKO(1935) | MEMORY STAT | vsize 2569MB | residentFast 444MB | heapAllocated 189MB
[task 2018-03-19T23:36:29.250Z] 23:36:29     INFO - TEST-OK | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | took 2633ms
[task 2018-03-19T23:36:29.291Z] 23:36:29     INFO - checking window state
In the last 7 days we have 47 failures.
They occur on linux64-jsdcov (opt).
Here is a recent log example:https://treeherder.mozilla.org/logviewer.html#?job_id=170540182&repo=mozilla-central&lineNumber=2797
and a relevant part of it:
[task 2018-03-27T12:50:42.687Z] 12:50:42     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js | recording-device-events notification unexpected - Got 1, expected 0
[task 2018-03-27T12:50:42.688Z] 12:50:42     INFO - Stack trace:
[task 2018-03-27T12:50:42.688Z] 12:50:42     INFO - chrome://mochikit/content/browser-test.js:test_is:1280
[task 2018-03-27T12:50:42.688Z] 12:50:42     INFO - chrome://mochitests/content/browser/browser/base/content/test/webrtc/head.js:listener:228
[task 2018-03-27T12:50:42.689Z] 12:50:42     INFO - closing the stream
:drno, can you please have a look at this?
Flags: needinfo?(drno)
Whiteboard: [stockwell needswork]
Tooru, this problem seems to have started right on the day you landed bug 1442465. Can I ask you to check if this might be related?
Flags: needinfo?(drno) → needinfo?(arai.unmht)
I guess we need the similar fix as bug 1444007 for other cases,
to avoid mixing other tabs events/information.
So, it's failing here.

https://searchfox.org/mozilla-central/rev/57bbc1ac58816dc054df242948f3ecf75e12df5f/browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js#312
> {
>   desc: "getUserMedia screen sharing in a first process + screen sharing in a second process",
>   run: async function checkMultiProcessScreen() {
> ...
>     info("removing the second tab");
>     BrowserTestUtils.removeTab(tab);
> 
>     // When both tabs use the same content process, the frame script for the
>     // first tab receives observer notifications for things happening in the
>     // second tab, so let's clear the observer call counts before we cleanup
>     // in the first tab.
>     await ignoreObserversCalled();
> 
>     // Close the first tab's stream and verify that all indicators are removed.
>     await closeStream();

https://searchfox.org/mozilla-central/rev/57bbc1ac58816dc054df242948f3ecf75e12df5f/browser/base/content/test/webrtc/head.js#408
> async function closeStream(aAlreadyClosed, aFrameId) {
>   await expectNoObserverCalled();

https://searchfox.org/mozilla-central/rev/57bbc1ac58816dc054df242948f3ecf75e12df5f/browser/base/content/test/webrtc/head.js#231
> function expectNoObserverCalled() {
>   return new Promise(resolve => {
>     let mm = _mm();
>     mm.addMessageListener("Test:ExpectNoObserverCalled:Reply",
>                           function listener({data}) {
>       mm.removeMessageListener("Test:ExpectNoObserverCalled:Reply", listener);
>       for (let topic in data) {
>         if (!data[topic])
>           continue;
> 
>         is(data[topic], 0, topic + " notification unexpected");
>       }
>       resolve();
>     });
>     mm.sendAsyncMessage("Test:ExpectNoObserverCalled");

https://searchfox.org/mozilla-central/source/browser/base/content/test/webrtc/get_user_media_content_script.js#63
> addMessageListener("Test:ExpectNoObserverCalled", data => {
>   sendAsyncMessage("Test:ExpectNoObserverCalled:Reply", gObservedTopics);
>   gObservedTopics = {};
> });

What I changed is stop awaiting on SessionStore update after removeTab.
I'm not sure what kind of event it's observing tho, simple workaround here is to wait for SessionStore update here as well.
(of course it's just abusing, and it needs to wait for appropriate thing)
Flags: needinfo?(arai.unmht)
See Also: → 1450163
testing a workaround patch.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1701ee966fed124d1fc1eec7f30a54fdfc2f0aa2

I'd like to leave the actual fix to bug 1450163.
(given that there's one more case that's using waitForSessionStoreUpdate
Assignee: nobody → arai.unmht
Status: NEW → ASSIGNED
Applied the same workaround, that is to wait for SessionStore update, that is the same situation as before removeTab fix.
The actual fix this need would be wait for something that guarantees the recording-device-events will no more be dispatched after removing tab, but I'll leave it to bug 1450163.
also updated the bug number for pre-existing FIXME.
Attachment #8963866 - Flags: review?(dao+bmo)
Comment on attachment 8963866 [details] [diff] [review]
Wait for SessionStore update as a workaround in browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js

>+    // FIXME: This should wait for indicator update instead (bug 1450163).
>+    let sessionStorePromise = BrowserTestUtils.waitForSessionStoreUpdate(tab);
>     BrowserTestUtils.removeTab(tab);
>+    await sessionStorePromise;

Instead of this hack, can you fix this similarly to how I fixed bug 1444007?
Attachment #8963866 - Flags: review?(dao+bmo)
Thank you for reviewing!

(In reply to Dão Gottwald [::dao] from comment #10)
> Comment on attachment 8963866 [details] [diff] [review]
> Wait for SessionStore update as a workaround in
> browser/base/content/test/webrtc/
> browser_devices_get_user_media_multi_process.js
> 
> >+    // FIXME: This should wait for indicator update instead (bug 1450163).
> >+    let sessionStorePromise = BrowserTestUtils.waitForSessionStoreUpdate(tab);
> >     BrowserTestUtils.removeTab(tab);
> >+    await sessionStorePromise;
> 
> Instead of this hack, can you fix this similarly to how I fixed bug 1444007?

The issue here is a bit different.
it's catching unexpected recording-device-events event in `closeStream()`,
so I'm not sure waiting for `getActiveStreams(...).length == 0` is the right thing to do here.
(or, do you have any other ideas about what to wait for?)

I'll try it tomorrow, but I think it's better landing this patch and leave the right fix to bug 1450163.
(In reply to Tooru Fujisawa [:arai] from comment #11)
> it's catching unexpected recording-device-events event in `closeStream()`,

Are you saying this event being dispatched is a WebRTC bug, or that the test is fragile in not expecting that event?
(In reply to Dão Gottwald [::dao] from comment #12)
> (In reply to Tooru Fujisawa [:arai] from comment #11)
> > it's catching unexpected recording-device-events event in `closeStream()`,
> 
> Are you saying this event being dispatched is a WebRTC bug, or that the test
> is fragile in not expecting that event?

I haven't yet investigated the detail.
what I observed is that the test fails because it catches the event there.
I'm not sure what the event is, and whether the event is actually expected or not.

then, what I changed in bug 1442465 is, not to wait for SessionStore update after the removeTab.
just reverting the test to wait for SessionStore update (now explicitly) solves the failure,
so I applied that change here to stop the intermittent failure.
I think waiting for getActiveStreams(...).length == 0 is probably the right thing to do here.
Okay, here's try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4b5f68ab8997efb52cf9538f18389971506d3b61

looks like we should wait for `getActiveStreams(...).length == 1` there, since the first tab is not yet closed at that point.
I'll ask review if intermittent failure is not observed on try.
Okay, this patch seems to fix the intermittent failure
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4b5f68ab8997efb52cf9538f18389971506d3b61

As mentioned in the previous comment, the test should wait for the end of the stream for the second tab, but the stream for the first tab should remain,
so it waits for length==1.

I'll post another fix in bug 1450163.
Attachment #8963866 - Attachment is obsolete: true
Attachment #8965556 - Flags: review?(dao+bmo)
Comment on attachment 8965556 [details] [diff] [review]
Wait for the end of the second tab streams before continuing test for first tab in browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js.

>+    await TestUtils.waitForCondition(() => webrtcUI.getActiveStreams(true, true, true).length == 1);
>+
>     // When both tabs use the same content process, the frame script for the
>     // first tab receives observer notifications for things happening in the
>     // second tab, so let's clear the observer call counts before we cleanup
>     // in the first tab.
>     await ignoreObserversCalled();

Are you sure that TestUtils.waitForCondition will resolve before ignoreObserversCalled? If not, you should use Promise.all.
Attachment #8965728 - Flags: review?(dao+bmo) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/a3555e4774717ea62b9bf66f41d24d0d58e4c863
Bug 1447180 - Wait for the end of the second tab streams before continuing test for first tab in browser/base/content/test/webrtc/browser_devices_get_user_media_multi_process.js. r=dao
https://hg.mozilla.org/mozilla-central/rev/a3555e477471
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Whiteboard: [stockwell needswork] → [stockwell fixed:timing]
You need to log in before you can comment on or make changes to this bug.