Closed Bug 1405083 Opened 4 years ago Closed 8 months ago

Intermittent dom/media/webrtc/tests/test_getUserMedia_basicScreenshare.html | Test timed out.

Categories

(Core :: WebRTC: Audio/Video, defect, P3)

defect

Tracking

()

RESOLVED FIXED
89 Branch
Tracking Status
firefox89 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended])

Attachments

(11 files)

401.23 KB, image/jpeg
Details
339.70 KB, image/jpeg
Details
35.98 KB, image/png
Details
11.29 KB, image/png
Details
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
1.49 MB, image/png
Details
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
48 bytes, text/x-phabricator-request
Details | Review
Seems to have started when bug 1380346 landed.
Depends on: 1380346
The screenshot from the failure in comment 0 is pretty telling -- the canvas in fullscreen is all white.
Rank: 25
Component: Audio/Video → WebRTC: Audio/Video
Priority: P5 → P3
this is odd that we only fail on windows 10 (all configs of it) and 50 failures in 3 days.

:pehrsons, do you have anymore insight into why this might be happening?  Would you be able to help get this bug assigned to the right person?
Flags: needinfo?(apehrson)
Whiteboard: [stockwell needswork]
Yeah, I'm trying to reach out to graphics about this.

I didn't get any replies so far, but I'll ni? bas here to see where we can take it.

Bas, could you point me in the right direction for who might know about a fullscreen 2d canvas on windows being white? (see comment 3)
Flags: needinfo?(apehrson) → needinfo?(bas)
:bas, at almost 100 failures last week this is really frequent, can you help :pehrsons out?
I'm seeing this on macOS now, but only when I build with jya's icecream instructions at: https://github.com/jyavenard/mozilla-icecream

If I do a default build (no .mozconfig at all), I don't see this failure.
I see the same behavior as :mjf. Built opt with icecc from my macOS (10.12.6) laptop, I get a single pattern of 4 colored blocks that does not change.  When I build on the same machine sans a mozconfig, the test progresses through patterns. I have not tried building opt without icecc.
Opt build without icecc works as expected.
And, not surprisingly, the debug build using icecc hangs with the unchanging pattern just like the opt build using icecc.  Just fyi.
Odd. On a build that's broken, what do you see in a regular screenshare demo like https://mozilla.github.io/webrtc-landing/gum_test.html (click "Screen")?
Flags: needinfo?(na-g)
Flags: needinfo?(mfroman)
When I run the screenshare demo on the broken build I see a static image of what what on the screen when the demo started, and the cursor movement is shown.  FPS figures are updating.  However, moving windows around on the screen does _not_ show up.

When I run the screenshare demo in the working build I see an image of the screen with the "tunnel effect" (each of the screenshare windows is showing a smaller version of the screen).  FPS figures are updating, and window movement on the screen is shown as expected.

I'll grab a couple screen shots for clarity.
Flags: needinfo?(na-g)
Flags: needinfo?(mfroman)
I see the same thing as Michael. In the broken build I get a static screen including the mouse cursor at the time of capture. There is also a dynamically updating cursor.
Comment on attachment 8946308 [details]
NonWorkingBuildScreenShareDemo.jpeg

Oh, that's not good. And also weird.

Judging from the mouse cursor sizes is there one static and one moving, both part of the capture?
Flags: needinfo?(mfroman)
This smells like some sort of compiler/linker or mixed-SDK issue...  Do all the SDKs used match exactly?  (They'd better) and all the compiler options match exactly, and include paths?  And are any of the include paths system paths (which could be different?  Or can we verify they're all the same includes somehow, including those they pull in?
(In reply to Andreas Pehrson [:pehrsons] from comment #35)
> Comment on attachment 8946308 [details]
> NonWorkingBuildScreenShareDemo.jpeg
> 
> Oh, that's not good. And also weird.
> 
> Judging from the mouse cursor sizes is there one static and one moving, both
> part of the capture?

Yes exactly correct, one static and one moving mouse cursor.  The moving cursor seems to be the only thing updating in the capture.
Flags: needinfo?(mfroman)
So, I see a couple of cases recently where we are getting gray (236,237,231) instead of green, and there's a (gray) popup from the OS about an error unlocking a keychain:

https://treeherder.mozilla.org/logviewer.html#?job_id=173827645&repo=autoland&lineNumber=9020
https://taskcluster-artifacts.net/Jknb9ASvQumwsedBe_gw7A/0/public/test_info/mozilla-test-fail-screenshot_euMT_O.png

https://treeherder.mozilla.org/logviewer.html#?job_id=174470240&repo=mozilla-inbound&lineNumber=14115
https://taskcluster-artifacts.net/dOHE9xf-QhCrASDLQq4HkQ/0/public/test_info/mozilla-test-fail-screenshot_qk39jp.png


The other failures I see seem to be getting a blue (80,126,183) instead of a red, with no keychain popup. This shade of blue is close to (but not quite) the color of the desktop on these machines (screenshot from a different test):

https://taskcluster-artifacts.net/Dg0SDRWCTYa8roInRj1PYA/0/public/test_info/mozilla-test-fail-screenshot_iN231Z.png
Ping regarding keychain popups possibly throwing the screenshare tests off.
Flags: needinfo?(jlund)
(In reply to Byron Campen [:bwc] from comment #50)
> Ping regarding keychain popups possibly throwing the screenshare tests off.

ah, just seeing this needinfo now.

dhouse, last week you may remember one of our loan issues where the keychain kept asking for pw. Buildduty were able to loan the machine out without that prompt by re-imaging and reseting the keychain. However, it turns out this might be the very problem in automation. You can see the first two treeherder links in comment 49 failing to pass the screencapture test and the associated screenshot with the keychain prompt. Are you the right person to look at this?
Flags: needinfo?(jlund) → needinfo?(dhouse)
Jake, do you remember dealing with the keychain prompt for tests on osx before? I can dig into testing it and checking the configuration, but you might have some context here?
Flags: needinfo?(jwatkins)
There is a comment in puppet about the keychain for the build user:
```
            exec {
                # whenever the user password changes, we need to delete the keychain, otherwise
                # it will prompt on login
                'kill-builder-keychain':
                    command     => "/bin/rm -rf ${home}/Library/Keychains/login.keychain",
                    notify      => Exec['reboot_semaphore'],
                    refreshonly => true;
            

}
```(https://hg.mozilla.org/build/puppet/file/tip/modules/users/manifests/builder/account.pp#l114)

So the keychain for the user running the tasks *should be set up with the user's current password. If the password was changed without using puppet, or the keychain is split from the password in another way that this exec doesn't get called, then that would explain the keychain warning/popup.
I looked over the treeherder results and two mac minis are recorded as having this problem repeat over the past months (#408 appeared once, and another #321 is in for Jan 31, but it has a different failure):

#415, #0032
```
t-yosemite-r7-415     Wed May 2, 05:07:45
t-yosemite-r7-415     Sun Apr 29, 21:50:13
t-yosemite-r7-415     Sun Apr 29, 04:26:21
t-yosemite-r7-0032    Wed Apr 25, 16:18:31
t-yosemite-r7-0032    Mon Apr 23, 20:04:13
t-yosemite-r7-415     Mon Apr 23, 16:42:24
t-yosemite-r7-415     Fri Apr 20, 07:49:53
t-yosemite-r7-0032    Thu Apr 19, 00:54:52
t-yosemite-r7-415     Tue Apr 17, 20:57:41
t-yosemite-r7-408     Mon Apr 16, 16:42:01
t-yosemite-r7-0032    Sun Apr 15, 20:49:20
t-yosemite-r7-415     Fri Apr 13, 11:52:33
t-yosemite-r7-415     Thu Apr 12, 08:36:21
t-yosemite-r7-415     Fri Apr 6, 12:12:18
win10 Sat Mar 31, 05:37:12
win10 Sat Mar 30..
t-yosemite-r7-415   Thu Mar 29, 10:04:25
win10 Mar 29
t-yosemite-r7-415   Mon Mar 26, 05:07:31
win10 Mar 25
win10 Mar 25
win10 Mar 24
415     Sat Mar 24, 07:20:36
415     Fri Mar 23, 16:31:34
win10 Mar 23
win10 Mar 23
415     Thu Mar 22, 17:06:12
win10 Mar 17
415     Tue Mar 13, 08:28:55
win10 Feb 21,24(4x),25,27
415     Tue Feb 20, 04:02:45
win10 Feb 18
415     Sat Feb 17, 13:37:21
win10 Feb 15,16,17
415     Thu Feb 15, 12:26:25
win10 14,15(2x)
415     Tue Feb 13, 06:33:10
415     Mon Feb 12, 17:37:15
win10 Feb 11
415     Sat Feb 10, 10:53:02
win10 Feb 6,7,8
415     Mon Feb 5, 22:20:48
linux   Jan 31
321     Wed Jan 31, 11:16:46 ( tab crashed. no prompt in screenshot )
linux   Jan 31
win10   Jan 31
415     Tue Jan 23, 19:54:33
win10 Jan 3,7,9(2x),16,19
```
Flags: needinfo?(dhouse)
Depends on: 1459250
I've created bug 1459250 for rebuilding those two macs.
Flags: needinfo?(jwatkins)
(In reply to OrangeFactor Robot from comment #60)
> 35 failures in 632 pushes (0.055 failures/push) were associated with this
[...]
> https://treeherder.mozilla.org/intermittent-failures.html#/
> bugdetails?bug=1405083&startday=2018-05-21&endday=2018-05-27&tree=trunk

"Sun Apr 29, 2018 to Tue May 29, 2018 UTC. Intermittent dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out.
8 total failures"

Again the failures are all on t-yosemite-r7-415 

(In reply to Dave House [:dhouse] from comment #57)
> I've created bug 1459250 for rebuilding those two macs.

415 was rebuilt on May 4th.
The next comment from Orange factor should be affected because of this https://bugzilla.mozilla.org/show_bug.cgi?id=1270217#c22.
According to bug 1270217 comment 22 updating the default value for MACOS_DEPLOYMENT_TARGET from 10.7 to 10.9 make this permafail. I'm going to disable this test for now because without the patch in bug 1270217 local builds are broken for people building on Mac.
Pushed by jwatt@jwatt.org:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0ee6b755ab2e
Disable test_getUserMedia_basicScreenshare.html for now. r=permafail
(In reply to Michael Froman [:mjf] from comment #25)
> I'm seeing this on macOS now, but only when I build with jya's icecream
> instructions at: https://github.com/jyavenard/mozilla-icecream

Possibly due to the use of -mmacosx-version-min=10.11
Keywords: leave-open
Summary: Intermittent dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out. → [test disabled] Intermittent dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out.
I've spent several hours today looking for a lead that a non-media person might be able to find. No luck. Dan, would you be able to take a look at this or suggest someone better? The test now fails consistently when run locally. The screen capturing seems to be stuck at the initial captured frame, and no longer seems to updated (other than for the mouse cursor). I don't see anything useful in the system log, or in the console output from the test run (I may be missing something).
Flags: needinfo?(dminor)
At the time we did the last update from upstream webrtc.org, we still supported OS X 10.7 but they had already dropped support. This forced us to restore some older code, e.g. at [1]. If switching the minimum version of OS X is causing problems, there is likely a problem with the newer code. I filed Bug 1409018 to remove the ifdeffed code. I'll take a look at getting that fixed up.

The originally reported problem seemed to only happen on Windows 10, so it sounds like there are at least two separate things going on here.

[1] https://searchfox.org/mozilla-central/source/media/webrtc/trunk/webrtc/modules/desktop_capture/screen_capturer_mac.mm#323
Flags: needinfo?(dminor)
See Also: → 1409018
Test got reenabled in bug 1409018.
Summary: [test disabled] Intermittent dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out. → Intermittent dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out.
This has started becoming frequent on windows recently. Screenshots show that it's because of a windows update modal. Not sure who should look at this. jlund, can you help out again?
Flags: needinfo?(jlund)
(In reply to Andreas Pehrson [:pehrsons] from comment #89)
> Created attachment 9027834 [details]
> windows-needs-updates_2018-11-27
> 
> This has started becoming frequent on windows recently. Screenshots show
> that it's because of a windows update modal. Not sure who should look at
> this. jlund, can you help out again?

grenade, markco, I see from comment 88 that we are hitting these with windows cloud based instances. e.g. gecko-t-win10-64

Any ideas here?
Flags: needinfo?(rthijssen)
Flags: needinfo?(mcornmesser)
Flags: needinfo?(jlund)
we've put in patches for the windows update modal as part of bug 1510220 and a related problem in bug 1481628.

are we still seeing this issue since those patches?

for clarity,
- the bug 1510220 fix was implemented on gecko-t-win10-64 and gecko-t-win10-64-gpu yesterday in this patch: https://github.com/mozilla-releng/OpenCloudConfig/commit/c421eb8
- the same patch was applied to gecko-t-win10-64-hw and gecko-t-win10-64-ux (hardware) today in this patch: https://github.com/mozilla-releng/OpenCloudConfig/commit/3c874a7
- the bug 1481628 fix was applied to all win 10 workers (ec2 & hw) today in this patch: https://github.com/mozilla-releng/OpenCloudConfig/commit/3c874a7
Flags: needinfo?(rthijssen)
Flags: needinfo?(mcornmesser)

Since Bug 1558482 landed here: https://tinyurl.com/y2glf2yg this bug started having a very high failure rate: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-06-06&endday=2019-06-13&tree=all&bug=1405083

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=251680588&repo=mozilla-inbound&lineNumber=13760

[task 2019-06-13T16:16:18.486Z] 16:16:18 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out.
[task 2019-06-13T16:16:18.487Z] 16:16:18 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:275:18
[task 2019-06-13T16:16:18.487Z] 16:16:18 INFO - reportError@https://example.com/tests/SimpleTest/TestRunner.js:121:22
[task 2019-06-13T16:16:18.488Z] 16:16:18 INFO - TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:142:7
[task 2019-06-13T16:16:18.489Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.491Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.492Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.492Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.493Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.494Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.494Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.495Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.495Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.497Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.497Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.498Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.498Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.498Z] 16:16:18 INFO - setTimeout handler
TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.498Z] 16:16:18 INFO - setTimeout handlerTestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:163:5
[task 2019-06-13T16:16:18.499Z] 16:16:18 INFO - TestRunner.runTests/<@https://example.com/tests/SimpleTest/TestRunner.js:381:20
[task 2019-06-13T16:16:18.500Z] 16:16:18 INFO - promise callback
TestRunner.runTests@https://example.com/tests/SimpleTest/TestRunner.js:368:50
[task 2019-06-13T16:16:18.501Z] 16:16:18 INFO - RunSet.runtests@https://example.com/tests/SimpleTest/setup.js:201:14
[task 2019-06-13T16:16:18.502Z] 16:16:18 INFO - RunSet.runall@https://example.com/tests/SimpleTest/setup.js:180:12
[task 2019-06-13T16:16:18.502Z] 16:16:18 INFO - hookupTests@https://example.com/tests/SimpleTest/setup.js:273:12
[task 2019-06-13T16:16:18.503Z] 16:16:18 INFO - parseTestManifest@https://example.com/manifestLibrary.js:36:5
[task 2019-06-13T16:16:18.503Z] 16:16:18 INFO - getTestManifest/req.onload@https://example.com/manifestLibrary.js:49:11
[task 2019-06-13T16:16:18.504Z] 16:16:18 INFO - EventHandlerNonNullgetTestManifest@https://example.com/manifestLibrary.js:45:3
[task 2019-06-13T16:16:18.505Z] 16:16:18 INFO - hookup@https://example.com/tests/SimpleTest/setup.js:253:5
[task 2019-06-13T16:16:18.506Z] 16:16:18 INFO - EventHandlerNonNull
@https://example.com/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-06-13T16:16:18.507Z] 16:16:18 INFO - Checking pixel against grey. Got [148,148,148,255] (NO)
[task 2019-06-13T16:16:18.508Z] 16:16:18 INFO - Checking pixel against grey. Got [148,148,148,255] (NO)
[task 2019-06-13T16:16:18.727Z] 16:16:18 INFO - Checking pixel against grey. Got [148,148,148,255] (NO)
[task 2019-06-13T16:16:18.977Z] 16:16:18 INFO - Checking pixel against grey. Got [148,148,148,255] (NO)
[task 2019-06-13T16:16:19.025Z] 16:16:19 INFO - GECKO(2565) | MEMORY STAT | vsize 20974980MB | residentFast 1056MB
[task 2019-06-13T16:16:19.087Z] 16:16:19 INFO - TEST-OK | dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | took 310800ms

Ryan, could you please take a look at this?

Flags: needinfo?(rhunt)
Regressed by: 1558482

Looks like bug 1558482 broke fullscreen somehow; here's a screenshot from one of the recent failures. This is a canvas element in fullscreen. The white part and the text on the right are both unexpected (and the reason the test is failing).

Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/98b09c54784f
disabled test_getUserMedia_basicScreenshare.html on linux64 r=aryx
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4a9c8e21ef23
add missing bracket on a CLOSED TREE

(In reply to Andreas Pehrson [:pehrsons] from comment #121)

Created attachment 9072109 [details]
Bug 1558482 fullscreen canvas regression, 2019-06-14

Looks like bug 1558482 broke fullscreen somehow; here's a screenshot from
one of the recent failures. This is a canvas element in fullscreen. The
white part and the text on the right are both unexpected (and the reason the
test is failing).

That sounds like a duplicate of bug 1559518 comment 4. I have a patch on that bug which should fix this hopefully.

Flags: needinfo?(rhunt)

(In reply to Ryan Hunt [:rhunt] from comment #129)

That sounds like a duplicate of bug 1559518 comment 4. I have a patch on that bug which should fix this hopefully.

That one's fixed now. I suppose we can re-enable this test then.

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/6db28048fd8a
Re-enable test_getUserMedia_basicScreenshare.html on linux64. r=rhunt

We're still seeing failures on OS 10.14, the screenshot seems to be grey:

https://taskcluster-artifacts.net/VpU4EwqnSc-hsIZVlJZ-_g/0/public/test_info/mozilla-test-fail-screenshot_HEedZn.png

Not sure if this regressed along with bug 1558482. It seems that the failures on OS 10.14 started on June 14, a day after the failures started on linux, but that may just be because the rate on OS 10.14 is much lower than it was on linux.

(In reply to Byron Campen [:bwc] from comment #139)

We're still seeing failures on OS 10.14, the screenshot seems to be grey:

https://taskcluster-artifacts.net/VpU4EwqnSc-hsIZVlJZ-_g/0/public/test_info/mozilla-test-fail-screenshot_HEedZn.png

Not sure if this regressed along with bug 1558482. It seems that the failures on OS 10.14 started on June 14, a day after the failures started on linux, but that may just be because the rate on OS 10.14 is much lower than it was on linux.

Another issue is this OS modal from a 10.14 machine.

IMO both of these cases indicate some other problem, since bug 1558482 was fixed but the grey screens on 10.14 continue.

Edwin, can you take a look? (Not sure if you're the right person for this, but I suspect you know who to bring it to)

Remembering to set the needinfo is good.

Flags: needinfo?(egao)

:pehrsons - comment 141 could be the way the macosx1014 machine are configured - I'm aware of at least one other failure caused by some OS-level UI notification on macosx1014.

Comment 137 I am not as sure about - got no leads.

Pinging :dividehex and :dhouse - does the modal from comment 141 look like an OS configuration issue? How about comment 137, is that a test issue?

Flags: needinfo?(jwatkins)
Flags: needinfo?(egao)
Flags: needinfo?(dhouse)

(In reply to Edwin Gao (:egao) from comment #143)

:pehrsons - comment 141 could be the way the macosx1014 machine are configured - I'm aware of at least one other failure caused by some OS-level UI notification on macosx1014.

Comment 137 I am not as sure about - got no leads.

Pinging :dividehex and :dhouse - does the modal from comment 141 look like an OS configuration issue? How about comment 137, is that a test issue?

Yes, that looks like wifi turned on and connected to the datacenter's wifi automatically. I'll talk with :dividehex about it and look for how to prevent this.

Depends on: 1570375

(In reply to Dave House [:dhouse] from comment #144)

(In reply to Edwin Gao (:egao) from comment #143)

:pehrsons - comment 141 could be the way the macosx1014 machine are configured - I'm aware of at least one other failure caused by some OS-level UI notification on macosx1014.

Comment 137 I am not as sure about - got no leads.

Pinging :dividehex and :dhouse - does the modal from comment 141 look like an OS configuration issue? How about comment 137, is that a test issue?

Yes, that looks like wifi turned on and connected to the datacenter's wifi automatically. I'll talk with :dividehex about it and look for how to prevent this.

I've turned off wifi on the mojave workers.

Flags: needinfo?(jwatkins)
Flags: needinfo?(dhouse)

I recall that this issue at one point was affecting quite many macosx1014 workers, though that now seems under control - only intermittently does this appear.

I'm now working on standing up the migration to Debian 10, and it seems this failure crops up on a permanent basis on Debian 10 test image.

Try: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=13513111a9183259074f1cfeaf773f37146be166
Log: https://taskcluster-artifacts.net/UKVnwuJbRgKmxygNihff4Q/0/public/logs/live_backing.log

Excerpt:

[task 2019-10-18T17:33:02.133Z] 17:33:02     INFO - TEST-START | dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html
[task 2019-10-18T17:33:02.189Z] 17:33:02     INFO - GECKO(3550) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-10-18T17:33:02.189Z] 17:33:02     INFO - GECKO(3550) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-10-18T17:33:02.291Z] 17:33:02     INFO - GECKO(3550) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-10-18T17:33:02.292Z] 17:33:02     INFO - GECKO(3550) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-10-18T17:33:02.397Z] 17:33:02     INFO - GECKO(3550) | [Parent 3550, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-10-18T17:33:02.397Z] 17:33:02     INFO - GECKO(3550) | (firefox:3550): Gtk-CRITICAL **: 17:33:02.392: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-10-18T17:33:02.412Z] 17:33:02     INFO - GECKO(3550) | [Parent 3550, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-10-18T17:33:02.413Z] 17:33:02     INFO - GECKO(3550) | (firefox:3550): Gtk-CRITICAL **: 17:33:02.400: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-10-18T17:33:03.579Z] 17:33:03     INFO - GECKO(3550) | [Child 3603: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f65d79ce400
[task 2019-10-18T17:33:03.599Z] 17:33:03     INFO - GECKO(3550) | [Child 3603: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f65d7b8a000
[task 2019-10-18T17:33:04.861Z] 17:33:04     INFO - GECKO(3550) | [Child 3603: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f65d3226800
[task 2019-10-18T17:33:04.865Z] 17:33:04     INFO - GECKO(3550) | [Child 3603: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f65d344b400
[task 2019-10-18T17:33:05.455Z] 17:33:05     INFO - GECKO(3550) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-10-18T17:33:05.456Z] 17:33:05     INFO - GECKO(3550) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-10-18T17:33:05.497Z] 17:33:05     INFO - GECKO(3550) | [Parent 3550, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-10-18T17:33:05.498Z] 17:33:05     INFO - GECKO(3550) | (firefox:3550): Gtk-CRITICAL **: 17:33:05.494: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-10-18T17:33:05.515Z] 17:33:05     INFO - GECKO(3550) | [Parent 3550, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-10-18T17:33:05.515Z] 17:33:05     INFO - GECKO(3550) | (firefox:3550): Gtk-CRITICAL **: 17:33:05.508: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-10-18T17:33:08.470Z] 17:33:08     INFO - GECKO(3550) | [Child 3603: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f65d5dc0c00
[task 2019-10-18T17:33:08.471Z] 17:33:08     INFO - GECKO(3550) | [Child 3603: Socket Thread]: D/DataChannel Deleting DataChannelConnection 0x7f65d6039000
[task 2019-10-18T17:38:13.528Z] 17:38:13     INFO - TEST-INFO | started process screentopng
[task 2019-10-18T17:38:13.630Z] 17:38:13     INFO - TEST-INFO | screentopng: exit 0
[task 2019-10-18T17:38:13.631Z] 17:38:13     INFO - <snipped 1216 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2019-10-18T17:38:13.631Z] 17:38:13     INFO - Buffered messages logged at 17:37:48
[task 2019-10-18T17:38:13.632Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.633Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.633Z] 17:38:13     INFO - Buffered messages logged at 17:37:49
[task 2019-10-18T17:38:13.634Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.634Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.634Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.635Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.635Z] 17:38:13     INFO - Buffered messages logged at 17:37:50
[task 2019-10-18T17:38:13.635Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.636Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.636Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.636Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.636Z] 17:38:13     INFO - Buffered messages logged at 17:37:51
[task 2019-10-18T17:38:13.640Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.641Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.641Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.642Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.642Z] 17:38:13     INFO - Buffered messages logged at 17:37:52
[task 2019-10-18T17:38:13.643Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.648Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.648Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.648Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.649Z] 17:38:13     INFO - Buffered messages logged at 17:37:53
[task 2019-10-18T17:38:13.649Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.649Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.650Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.650Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.651Z] 17:38:13     INFO - Buffered messages logged at 17:37:54
[task 2019-10-18T17:38:13.651Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.651Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.651Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.652Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.652Z] 17:38:13     INFO - Buffered messages logged at 17:37:55
[task 2019-10-18T17:38:13.653Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.653Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.653Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.653Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.654Z] 17:38:13     INFO - Buffered messages logged at 17:37:56
[task 2019-10-18T17:38:13.654Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.654Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.655Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.655Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.656Z] 17:38:13     INFO - Buffered messages logged at 17:37:57
[task 2019-10-18T17:38:13.656Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.656Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.657Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.657Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.657Z] 17:38:13     INFO - Buffered messages logged at 17:37:58
[task 2019-10-18T17:38:13.658Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.658Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.659Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.659Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.659Z] 17:38:13     INFO - Buffered messages logged at 17:37:59
[task 2019-10-18T17:38:13.660Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.660Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.660Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.661Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.661Z] 17:38:13     INFO - Buffered messages logged at 17:38:00
[task 2019-10-18T17:38:13.662Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.662Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.662Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.663Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.664Z] 17:38:13     INFO - Buffered messages logged at 17:38:01
[task 2019-10-18T17:38:13.664Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.665Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.665Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.665Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.666Z] 17:38:13     INFO - Buffered messages logged at 17:38:02
[task 2019-10-18T17:38:13.666Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.666Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.667Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.667Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.668Z] 17:38:13     INFO - Buffered messages logged at 17:38:03
[task 2019-10-18T17:38:13.669Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.669Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.669Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.670Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.670Z] 17:38:13     INFO - Buffered messages logged at 17:38:04
[task 2019-10-18T17:38:13.671Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.673Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.673Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.673Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.674Z] 17:38:13     INFO - Buffered messages logged at 17:38:05
[task 2019-10-18T17:38:13.674Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.674Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.675Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.675Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.675Z] 17:38:13     INFO - Buffered messages logged at 17:38:06
[task 2019-10-18T17:38:13.676Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.683Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.684Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.684Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.684Z] 17:38:13     INFO - Buffered messages logged at 17:38:07
[task 2019-10-18T17:38:13.685Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.685Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.685Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.686Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.686Z] 17:38:13     INFO - Buffered messages logged at 17:38:08
[task 2019-10-18T17:38:13.687Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.687Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.687Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.688Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.688Z] 17:38:13     INFO - Buffered messages logged at 17:38:09
[task 2019-10-18T17:38:13.689Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.689Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.690Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.690Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.690Z] 17:38:13     INFO - Buffered messages logged at 17:38:10
[task 2019-10-18T17:38:13.691Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.691Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.692Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.692Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.692Z] 17:38:13     INFO - Buffered messages logged at 17:38:11
[task 2019-10-18T17:38:13.693Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.693Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.693Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.694Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.694Z] 17:38:13     INFO - Buffered messages logged at 17:38:12
[task 2019-10-18T17:38:13.694Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.695Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.695Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.695Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.696Z] 17:38:13     INFO - Buffered messages logged at 17:38:13
[task 2019-10-18T17:38:13.696Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.697Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:13.697Z] 17:38:13     INFO - Buffered messages finished
[task 2019-10-18T17:38:13.698Z] 17:38:13     INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out. 
[task 2019-10-18T17:38:13.699Z] 17:38:13     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:277:18
[task 2019-10-18T17:38:13.699Z] 17:38:13     INFO - reportError@https://example.com/tests/SimpleTest/TestRunner.js:121:22
[task 2019-10-18T17:38:13.699Z] 17:38:13     INFO - TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:142:18
[task 2019-10-18T17:38:13.699Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.700Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.700Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.700Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - setTimeout handler*TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:15
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - TestRunner.runTests/<@https://example.com/tests/SimpleTest/TestRunner.js:388:20
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - promise callback*TestRunner.runTests@https://example.com/tests/SimpleTest/TestRunner.js:375:50
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - RunSet.runtests@https://example.com/tests/SimpleTest/setup.js:201:14
[task 2019-10-18T17:38:13.701Z] 17:38:13     INFO - RunSet.runall@https://example.com/tests/SimpleTest/setup.js:180:12
[task 2019-10-18T17:38:13.702Z] 17:38:13     INFO - hookupTests@https://example.com/tests/SimpleTest/setup.js:273:12
[task 2019-10-18T17:38:13.702Z] 17:38:13     INFO - parseTestManifest@https://example.com/manifestLibrary.js:48:13
[task 2019-10-18T17:38:13.702Z] 17:38:13     INFO - getTestManifest/req.onload@https://example.com/manifestLibrary.js:61:28
[task 2019-10-18T17:38:13.702Z] 17:38:13     INFO - EventHandlerNonNull*getTestManifest@https://example.com/manifestLibrary.js:57:3
[task 2019-10-18T17:38:13.702Z] 17:38:13     INFO - hookup@https://example.com/tests/SimpleTest/setup.js:253:20
[task 2019-10-18T17:38:13.702Z] 17:38:13     INFO - EventHandlerNonNull*@https://example.com/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2019-10-18T17:38:13.756Z] 17:38:13     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:14.012Z] 17:38:14     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:14.257Z] 17:38:14     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:14.513Z] 17:38:14     INFO - Checking pixel against green. Got [76,166,2,255] (NO)
[task 2019-10-18T17:38:14.529Z] 17:38:14     INFO - GECKO(3550) | MEMORY STAT | vsize 2593MB | residentFast 196MB | heapAllocated 22MB
[task 2019-10-18T17:38:14.529Z] 17:38:14     INFO - TEST-OK | dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | took 312395ms

Looks like it is failing in the setup? I am not too sure, but this is something that ideally I'd like to have a directive on prior to enabling Debian 10 for the linux test platform (disable, hold for a fix, etc).

:pehrsons - what are the intricacies involved in this test? (screen resolution, audio device, video codec, etc). I have had issues getting the Debian 10 test image to behave as I want to but I've been able to eliminate all failures from mda2 with the exception of this test.

Flags: needinfo?(apehrson)

It draws a canvas in fullscreen mode, runs a screen capture through getUserMedia to get access to the frames of the screen and checks some pixels in the video track to see that it is indeed capturing the screen correctly.

The most revealing for this test when the color checks fail is to look at the screenshot. On Mac this revealed a modal popup covering Firefox for instance. In this case there appears to be something wrong with rendering the canvas element in fullscreen: https://taskcluster-artifacts.net/CVMeBnukQmGF_6gLJuOj5g/0/public/test_info//mozilla-test-fail-screenshot_X6BpeT.png

The test assumes that the canvas is centered on the screen, but here it is offset to the top left for some reason.

The test just puts a canvas of size 20x20 in fullscreen, so it not being scaled to fill the most narrow dimension of the screen (height in this case) naively seems like a fullscreen bug to me. I'm not sure who could help with that.

Flags: needinfo?(apehrson)
Keywords: leave-open
Whiteboard: [stockwell disabled] → [stockwell fixed:other]

In the past week there were 22 failures of this bug, on linux1804-64 debug, linux1804-64-shippable-qr opt, windows10-aarch64 opt.
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-06-14&endday=2020-06-21&tree=trunk&bug=1405083

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306937957&repo=autoland&lineNumber=15547

:jib, could you assign someone to take a look, please?

Flags: needinfo?(jib)
Whiteboard: [stockwell fixed:other] → [stockwell needswork:owner]

In the last 7 days there have been 26 occurrences on linux1804-64, macosx1014-64, windows10-aarch64, build types opt and debug.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=308635966&repo=mozilla-central&lineNumber=18260

In the last 7 days there have been 27 occurrences, most on linux1804-64, some on windows10-aarch64 opt and debug.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=310265304&repo=mozilla-central&lineNumber=20805

In last 7 days this bug failed 31 times. This happend on linux1804-64, linux1804-64-asan, linux1804-64-shippable-qr, windows10-aarch64 opt and debug build types.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=311031571&repo=autoland&lineNumber=16514

The windows failures seem to be a modal from Windows Defender Firewall blocking Firefox, like [1]. Dave, would you know what to do about this?
On linux there is a warning of an XML parsing error in webrtcindicator.xhtml in a window on top of fullscreen, that appears to have started June 11, after bug 1643545 landed. Mike, can you take a look?

[1] https://firefoxci.taskcluster-artifacts.net/W0wxuxBzQP-2t3MsKz3_5Q/0/public/test_info/mozilla-test-fail-screenshot_bczy6x.png

Flags: needinfo?(mconley)
Flags: needinfo?(dhouse)
Regressed by: 1643545

redirecting :dhouse -> :markco for win/aarch64 question

Flags: needinfo?(dhouse) → needinfo?(mcornmesser)
Attached image WinDefender.PNG

Windows Defender is currently disabled. Verified by Smart Bear. What was the behavior that was indicating it could be Windows Defender?

Flags: needinfo?(mcornmesser)

odd, I see the same screenshot with windows defender blocking firefox nightly on this same test while running mochitest-media on datacenter hardware (win10x64 same as we run perf on):
https://firefoxci.taskcluster-artifacts.net/MYVl-ItVRMi2Mgrv2y0CWQ/0/public/test_info/mozilla-test-fail-screenshot_item46.png

here is a try push:
https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=e4-kBlVfQgeHYCeoSzgl4w.0&revision=33e9256c3f5ffdf0f9c484ec61e2b0e1c33ec5cd&searchStr=mda

I run this locally and don't get the defender message; curious why we see this on hardware even though we have disabled the firewall and we don't see this for other situations. Maybe share screen requires other permissions at the OS level?

I also looked at the screenshot and there is a windows defender firewall which could be what needs to be disabled. It is in the state of running

Flags: needinfo?(bas)

(In reply to Mark Cornmesser [:markco] from comment #207)

Created attachment 9168539 [details]
WinDefender.PNG

Windows Defender is currently disabled. Verified by Smart Bear. What was the behavior that was indicating it could be Windows Defender?

See the screenshot in comment 208. Pick any recent windows failure from the intermittent failures view and the screenshot will look the same. If it's passing on some configurations of Windows but not others, maybe the location of the modal, or the resolution differs? The test looks at some pixels in each quadrant but not all.

Flags: needinfo?(mcornmesser)

I don't think we want to disable the firewall. Particularly with these nodes being on a network we don't manage. The challenge here is adding a firewall exception for the process. Because the process path changes with each new task user. I will take a deeper look into it Monday afternoon.

Rob, We talk about similar issue previously. Any ideas?

Flags: needinfo?(mcornmesser) → needinfo?(rthijssen)

Given that this doesn't always fail, it is possible that this message window is always present, and that failure is unrelated.

Flags: needinfo?(mcornmesser)

(In reply to Mark Cornmesser [:markco] from comment #212)

I don't think we want to disable the firewall. Particularly with these nodes being on a network we don't manage. The challenge here is adding a firewall exception for the process. Because the process path changes with each new task user. I will take a deeper look into it Monday afternoon.

Rob, We talk about similar issue previously. Any ideas?

in the longer term, now that we manage the sysprep lifecycle in automation (for azure images), we should probably add the firewall exceptions to the default profile during cloud disk/machine image builds.

for the short term, there's no good solution for tasks that don't run elevated. this comes up every once in a while and there is some history in bug 1535467, comment 3.

Flags: needinfo?(rthijssen)

(In reply to Andreas Pehrson [:pehrsons] from comment #205)

On linux there is a warning of an XML parsing error in webrtcindicator.xhtml in a window on top of fullscreen, that appears to have started June 11, after bug 1643545 landed. Mike, can you take a look?

Hm, I'm not seeing the XML parsing error in the logs. Am I looking in the wrong place?

Flags: needinfo?(mconley) → needinfo?(apehrson)

(In reply to Mike Conley (:mconley) (:⚙️) from comment #216)

Hm, I'm not seeing the XML parsing error in the logs. Am I looking in the wrong place?

See a screenshot, like [1], which is from [2] (linux1804-64-qr opt).

[1] https://firefoxci.taskcluster-artifacts.net/dcGejwzqRVuBhxk_3h4VeA/0/public/test_info//mozilla-test-fail-screenshot_ASfNIq.png
[2] https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=fa0dbdf15f291e814b4854d515d7ef3e4548b7fb&selectedTaskRun=dcGejwzqRVuBhxk_3h4VeA.0

Flags: needinfo?(apehrson) → needinfo?(mconley)
Flags: needinfo?(mcornmesser)

(In reply to Mark Cornmesser [:markco] from comment #213)

Given that this doesn't always fail, it is possible that this message window is always present, and that failure is unrelated.

That failure is definitely related.

I added some logging to dump the image on which the pixel comparison fails.

It looks like this, and the pixel looked at for this case is [38,25] from the top left. This is in a part of the test where we ask the screensharing backend for a lower resolution, so the pixel looked at is several others blended -- which explains why that color cannot be found in the full-res screenshot (I tried). The log is (for now) available on treeherder.

I am not sure whether the dialog is present when the test passes, but as mentioned before the position of the dialog could play a role here.

Mark, could you help me find an owner for clearing the firewall dialog? Preferably in another bug. Thanks!

Flags: needinfo?(mcornmesser)

(In reply to Andreas Pehrson [:pehrsons] from comment #217)

[1] https://firefoxci.taskcluster-artifacts.net/dcGejwzqRVuBhxk_3h4VeA/0/public/test_info//mozilla-test-fail-screenshot_ASfNIq.png
[2] https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=fa0dbdf15f291e814b4854d515d7ef3e4548b7fb&selectedTaskRun=dcGejwzqRVuBhxk_3h4VeA.0

Thanks. That is... bizarre. The webrtcIndicator.xhtml file definitely has a root element. I would expect breakage all over the place from the browser/base/content/test/webrtc tests were it invalid. So something is up with loading this file from the omni.ja intermittently - either we can't get at the file, or we're somehow screwing up parsing it. If this got introduced by bug 1643545, maybe it doesn't like the comment block that was added in https://phabricator.services.mozilla.com/D78914 in place of the preprocessed stuff? But I can't imagine how that'd be race-y... maybe someone who knows the HTML parser would know? Tagging in gandalf in case he has thoughts.

Flags: needinfo?(mconley) → needinfo?(gandalf)

I'm not very familiar with the parser, but the screenshot YSOD looks like the document is empty. I'm not sure why would it be empty tho.

One thing to try is to move it to .html which should be possible here, and see if HTML parser shows empty page or something more interesting.

Flags: needinfo?(gandalf)

Mark, could you help me find an owner for clearing the firewall dialog? Preferably in another bug. Thanks!

I have a blocking bug open. I will see if i can come up with a way to either address this through the setting with the network profile or failing that a way to suppress the notification. As mentioned in Comment 215 previously we have not found a good solution for it, so that is the reason why I am going to try some indirect routes. It will be early/mid next week when i have a chance to take a look at.

For Windows is this only affecting aarch64 workers?

Flags: needinfo?(mcornmesser)

(In reply to Mark Cornmesser [:markco](PTO till 8-17 ) from comment #221)

I have a blocking bug open. I will see if i can come up with a way to either address this through the setting with the network profile or failing that a way to suppress the notification. As mentioned in Comment 215 previously we have not found a good solution for it, so that is the reason why I am going to try some indirect routes. It will be early/mid next week when i have a chance to take a look at.

Thanks. It's not awfully frequent so priority follows that.

For Windows is this only affecting aarch64 workers?

That's the only place we've seen failures, but per comment 208 the dialog shows on datacenter hardware too.

In the last 7 days there have been 22 occurrences on windows10-aarch64, macosx1014-64 and linux1804-64 debug and opt.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=313724460&repo=autoland&lineNumber=17096

Mark, could you, please, take a look?

Flags: needinfo?(mcornmesser)

I have been looking at this again this morning.

2 things to note. I tried to come at this by setting a firewall rule using the %USERPROFILE% variable in the process directory path through the generic-worker wrapper script. The firewall rule created but with the path to a temp profile and not the current user profile. C:\windows\system32\config\systemprofile\build\application\firefox\firefox.exe instead of C:\users$taskuser\build\application\firefox\firefox.exe .

There registry setting that can be set HKEY_CURRENT_USER\SOFTWARE\Policies\Microsoft\Windows\Explorer\DisableNotificationCenter when set to the value of 1 should disable the desktop notification. However, with aarchx64 the registry is not as straight forward was other architectures. I will contact bitbar and do some testing this week to see if we can down this route.

Leaving the NI in place so I remember to come back to this bug.

There registry setting that can be set HKEY_CURRENT_USER\SOFTWARE\Policies\Microsoft\Windows\Explorer\DisableNotificationCenter when set to the value of 1 should disable the desktop notification. However, with aarchx64 the registry is not as straight forward was other architectures. I will contact bitbar and do some testing this week to see if we can down this route.

This won't work either because it is in the hkcu hive which is not available to our start scripts. I am going continue down the route of trying to suppress the notification.

I also see this when running the test on moonshots, so I think this is a common problem- happy to help test theories or setup scripts if there is a recommendation

Rob; Could you implement something like this in OCC for the Yogas?

$network = ((Get-NetConnectionProfile).name)

Set-NetConnectionProfile -Name "$network" -NetworkCategory Private
netsh firewall set notifications mode = disable profile = all

This should change the network category to private. Once that is set we can turn off the firewall notifications. I am asking because you are more familiar with the Yogas and OCC than I am.

Flags: needinfo?(mcornmesser) → needinfo?(rthijssen)

:markco, can you do that for the moonshots? or is that something I could setup in something like:
https://searchfox.org/mozilla-central/source/testing/mozharness/configs/unittests/win_unittest.py#231

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #228)

I also see this when running the test on moonshots, so I think this is a common problem- happy to help test theories or setup scripts if there is a recommendation

I think what is commands in comment 229 will work on the moonshots. I will spin up a couple test machines with it this week and let you know.

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #230)

:markco, can you do that for the moonshots? or is that something I could setup in something like:
https://searchfox.org/mozilla-central/source/testing/mozharness/configs/unittests/win_unittest.py#231

I think this should go into the base configuration. I will get something up this week to test on.

(In reply to Mark Cornmesser [:markco] from comment #229)

Rob; Could you implement something like this in OCC for the Yogas?

$network = ((Get-NetConnectionProfile).name)

Set-NetConnectionProfile -Name "$network" -NetworkCategory Private
netsh firewall set notifications mode = disable profile = all

This should change the network category to private. Once that is set we can turn off the firewall notifications. I am asking because you are more familiar with the Yogas and OCC than I am.

should be very straightforward depending on when you need it to happen. i'd wrap it in something like:

if (${env:PROCESSOR_ARCHITEW6432} -eq 'ARM64') {
  # yoga specific code
}

because lots of the other worker types specifically want different network profiles in force at different times in the bootstrapping lifecycle.

Flags: needinfo?(rthijssen)

It seems the only way to get the notifications consistently disabled is to run it out of the generic-worker wrapper script. Which leads me to believe that it was closely linked to the user account. It seems to work, so the next step will be to run tasks and see if it has the desired outcome. If it does i will roll up an OCC and a Ronin Puppet patch to deploy it.

jmaher: I am deploying a 3 node test pool this afternoon. The workerType is gecko-t-win10-64-ht.

Flags: needinfo?(jmaher)

I could reproduce this on windows10 moonshots (what we don't normally run on) and the changes :markco made are working great:
https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=cJdywOPoSSmn-o39bhhy2A.0&searchStr=windows10-64%2Cmochitest-media&revision=b1a215ba6445a22ead7d0a74f7e377a9004255f0

I would assume this would fix it for win10/aarch64, if not it should be really close.

Flags: needinfo?(jmaher)

This change is going out the aarch64 workers today. I have contacted Bitbar and ask them to do spot checks this afternoon for any issues.

No more Windows issues since the 12th. Thanks for seeing this through Mark!

Mark, there are still some occurrences on win10 aarch64. Most were on beta but there's also this one on m-c. Is that expected?

Flags: needinfo?(mcornmesser)

(In reply to Andreas Pehrson [:pehrsons] from comment #245)

Mark, there are still some occurrences on win10 aarch64. Most were on beta but there's also this one on m-c. Is that expected?

What is the best way to find occurrences of this error? I wondering if this is a particular host or if we are seeing this randomly.

See the link provided by Intermittent Failures Robot, such as in comment 244. On that intermittent failures view on treeherder you can choose a range by date and sort by platform to find just the windows failures, for instance. To verify it is the firewall modal issue I click on the failure's Revision to get to the job in treeherder, and from the artifacts tab find and open the mozilla-test-fail-screenshot_xxxxxx.png

It seems to be one win10 aarch64 worker that is failing, t-lenovoyogac630-025. I will contact Bitbar and see if we can force it to update.

(In reply to Mark Cornmesser [:markco] from comment #248)

It seems to be one win10 aarch64 worker that is failing, t-lenovoyogac630-025. I will contact Bitbar and see if we can force it to update.

For some reason this particular laptop refused to update. 022 has been bootstrapped and set up as a replacement. If it has no issues over the weekend Bitbar will remove 025 from the pool and have it permanently replaced with 022.

Flags: needinfo?(mcornmesser)
Summary: Intermittent dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html | Test timed out. → Intermittent dom/media/webrtc/tests/test_getUserMedia_basicScreenshare.html | Test timed out.

022 failed to pick up tasks, so we are still working on replacing 025.

Whiteboard: [stockwell unknown] → [stockwell needswork:owner]
Depends on: 1676167

There are 40 total failures in the last 7 days on linux mac and windows

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=321732334&repo=mozilla-central&lineNumber=22605

task 2020-11-13T18:35:22.798Z] 18:35:22 INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html
[task 2020-11-13T18:35:22.921Z] 18:35:22 INFO - GECKO(12740) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2020-11-13T18:35:22.922Z] 18:35:22 INFO - GECKO(12740) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2020-11-13T18:35:23.286Z] 18:35:23 INFO - GECKO(12740) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2020-11-13T18:35:23.288Z] 18:35:23 INFO - GECKO(12740) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2020-11-13T18:35:23.350Z] 18:35:23 INFO - GECKO(12740) | 1605292523341 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-11-13T18:35:26.504Z] 18:35:26 INFO - GECKO(12740) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2020-11-13T18:35:26.506Z] 18:35:26 INFO - GECKO(12740) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2020-11-13T18:35:26.518Z] 18:35:26 INFO - GECKO(12740) | JavaScript error: resource://gre/actors/PictureInPictureChild.jsm, line 298: InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable
[task 2020-11-13T18:35:26.550Z] 18:35:26 INFO - GECKO(12740) | 1605292526537 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-11-13T18:40:42.336Z] 18:40:42 INFO - GECKO(12740) | 1605292842319 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates
[task 2020-11-13T18:40:44.611Z] 18:40:44 INFO - TEST-INFO | started process screenshot
[task 2020-11-13T18:40:44.904Z] 18:40:44 INFO - TEST-INFO | screenshot: exit 0
[task 2020-11-13T18:40:44.905Z] 18:40:44 INFO - <snipped 1234 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2020-11-13T18:40:44.907Z] 18:40:44 INFO - Buffered messages logged at 18:40:19
[task 2020-11-13T18:40:44.908Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.910Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.911Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.915Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.916Z] 18:40:44 INFO - Buffered messages logged at 18:40:20
[task 2020-11-13T18:40:44.918Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.920Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.922Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.923Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.925Z] 18:40:44 INFO - Buffered messages logged at 18:40:21
[task 2020-11-13T18:40:44.926Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.928Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.930Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.932Z] 18:40:44 INFO - Buffered messages logged at 18:40:22
[task 2020-11-13T18:40:44.934Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.935Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.937Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.938Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.940Z] 18:40:44 INFO - Buffered messages logged at 18:40:23
[task 2020-11-13T18:40:44.941Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.943Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.944Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.945Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.947Z] 18:40:44 INFO - Buffered messages logged at 18:40:24
[task 2020-11-13T18:40:44.948Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.949Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.951Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.952Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.954Z] 18:40:44 INFO - Buffered messages logged at 18:40:25
[task 2020-11-13T18:40:44.955Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.959Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.960Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.961Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.963Z] 18:40:44 INFO - Buffered messages logged at 18:40:26
[task 2020-11-13T18:40:44.964Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.966Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.967Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.968Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.970Z] 18:40:44 INFO - Buffered messages logged at 18:40:27
[task 2020-11-13T18:40:44.971Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.974Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.976Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.977Z] 18:40:44 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:44.978Z] 18:40:44 INFO - Buffered messages logged at 18:40:28

[task 2020-11-13T18:40:45.104Z] 18:40:45 INFO - Buffered messages logged at 18:40:44
[task 2020-11-13T18:40:45.105Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.107Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.109Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.110Z] 18:40:45 INFO - Buffered messages finished
[task 2020-11-13T18:40:45.113Z] 18:40:45 INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html | Test timed out.
[task 2020-11-13T18:40:45.114Z] 18:40:45 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2020-11-13T18:40:45.115Z] 18:40:45 INFO - reportError@https://example.com/tests/SimpleTest/TestRunner.js:143:22
[task 2020-11-13T18:40:45.115Z] 18:40:45 INFO - TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:165:18
[task 2020-11-13T18:40:45.116Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.117Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.347Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.609Z] 18:40:45 INFO - Checking pixel against green. Got [188,255,190,255] (NO)
[task 2020-11-13T18:40:45.650Z] 18:40:45 INFO - GECKO(12740) | MEMORY STAT | vsize 6799MB | vsizeMaxContiguous 73327491MB | residentFast 111MB | heapAllocated 14MB
[task 2020-11-13T18:40:45.671Z] 18:40:45 INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html | took 322862ms
[task 2020-11-13T18:40:45.705Z] 18:40:45 INFO - GECKO(12740) | JavaScript error: resource://gre/actors/PictureInPictureChild.jsm, line 568: TypeError: can't access property "removeEventListener", this.contentWindow is null
[task 2020-11-13T18:40:45.714Z] 18:40:45 INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicTabshare.html

Flags: needinfo?(jib)

There are 24 total failures in the last 7 days on linux1804-64-qr opt, windows10-aarch64 opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=328454998&repo=autoland&lineNumber=19655

[task 2021-02-01T15:41:01.596Z] 15:41:01 INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html
[task 2021-02-01T15:41:01.800Z] 15:41:01 INFO - GECKO(5423) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-02-01T15:41:01.801Z] 15:41:01 INFO - GECKO(5423) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-02-01T15:41:02.003Z] 15:41:02 INFO - GECKO(5423) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-02-01T15:41:02.004Z] 15:41:02 INFO - GECKO(5423) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-02-01T15:41:05.726Z] 15:41:05 INFO - GECKO(5423) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-02-01T15:41:05.726Z] 15:41:05 INFO - GECKO(5423) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-02-01T15:46:04.119Z] 15:46:04 INFO - GECKO(5423) | 1612194364107 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates
[task 2021-02-01T15:46:07.673Z] 15:46:07 INFO - TEST-INFO | started process screentopng
[task 2021-02-01T15:46:07.899Z] 15:46:07 INFO - TEST-INFO | screentopng: exit 0
[task 2021-02-01T15:46:07.900Z] 15:46:07 INFO - <snipped 1213 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2021-02-01T15:46:07.902Z] 15:46:07 INFO - Buffered messages logged at 15:45:42
[task 2021-02-01T15:46:07.903Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.904Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.905Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.906Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.907Z] 15:46:07 INFO - Buffered messages logged at 15:45:43
[task 2021-02-01T15:46:07.908Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.909Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.910Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.910Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)

[task 2021-02-01T15:46:07.956Z] 15:46:07 INFO - Buffered messages logged at 15:46:06
[task 2021-02-01T15:46:07.956Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.957Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.957Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.957Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.958Z] 15:46:07 INFO - Buffered messages logged at 15:46:07
[task 2021-02-01T15:46:07.958Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.959Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.960Z] 15:46:07 INFO - Buffered messages finished
[task 2021-02-01T15:46:07.960Z] 15:46:07 INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html | Test timed out.
[task 2021-02-01T15:46:07.960Z] 15:46:07 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-02-01T15:46:07.960Z] 15:46:07 INFO - reportError@https://example.com/tests/SimpleTest/TestRunner.js:143:22
[task 2021-02-01T15:46:07.960Z] 15:46:07 INFO - TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:165:18
[task 2021-02-01T15:46:07.960Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:07.977Z] 15:46:07 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:08.222Z] 15:46:08 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:08.484Z] 15:46:08 INFO - Checking pixel against grey. Got [210,213,203,255] (NO)
[task 2021-02-01T15:46:08.669Z] 15:46:08 INFO - GECKO(5423) | MEMORY STAT | vsize 2734MB | residentFast 166MB | heapAllocated 13MB
[task 2021-02-01T15:46:08.678Z] 15:46:08 INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html | took 307089ms
Jan-Ivar can you assign someone to take a look?

Flags: needinfo?(jib)
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

Mark, 025 is still the main contributor here. Anything you can do?

Flags: needinfo?(jib) → needinfo?(mcornmesser)

I have sent an email to SmartBear (formerly BitBar) and asked them if we can swap 025 with one of the spares.

Flags: needinfo?(mcornmesser)

Update, SmartBear is still working on getting a replacement up and running.

It appears these mac failures are a result of some (?) macs having changed screen resolution from 1280x1024 to 1600x1200 -- I am judging this solely on the captured screenshots.

That means the aspect ratio has changed, and that affects how we scale the screen sharing tracks in the test. We request the screenshare to capture with a width and height between 10 and 100 pixels. It will retain the aspect ratio so these screen resolutions might scale a bit differently. 10 to 100 is quite small and it could be that a tested pixel is close enough to the black sides, or another quadrant, and falls outside the threshold.

When the macs fail we test for green (0, 255, 0) but get (46, 255, 6) with a threshold of 16 (meaning each r,g,b value can be up to 16 off the reference value).

Scaling down to a bit larger resolution than this should help stabilize this test against similar future changes. I don't want to change this too much because it has also helped catch real issues in the past, where perhaps a bar or popup is visible high on the screen and leaks into some of the tested pixels.

There have been 62 total failures in the last 7 days (recent failure log).
Affected platforms are:

  • macosx1014-64-shippable-qr
  • macosx1014-64-qr opt & debug
  • linux1804-64-shippable-qr & linux1804-64-qr opt
Whiteboard: [stockwell unknown] → [stockwell needswork]

Andreas are you working on this? Are there any updates?

Flags: needinfo?(apehrson)

I'll make an attempt with comment 281.

Flags: needinfo?(apehrson)

I'm planning to make the logging and failure paths of this test better, so the errors we're seeing here will stop being test timeouts. New bugs will need to be opened and I'll close this bug as I land patches.

Assignee: nobody → apehrson
Status: NEW → ASSIGNED

Joel, I'm seeing screenshots on Mac not having Firefox present in them. See for instance this one from this try push. Is this known, and if not, who can take a look at it?

Flags: needinfo?(jmaher)

this is common- I am not sure the right path to take here- in one case the mac is actually hardware that we maintain and use for testing and is logged in normally, the other case is this doesn't happen all the time and there is not a pattern I know of why it will work or not.

looking at m-c and failures on osx, I see devtools has a failure and a screenshot:
https://firefoxci.taskcluster-artifacts.net/EvxkL3SWQmaapFBwn7W2iQ/0/public/test_info/mozilla-test-fail-screenshot_SfaBkO.png

so does mochitest-media:
https://firefoxci.taskcluster-artifacts.net/YGWlyLzkT9W0dM79oWcnvQ/0/public/test_info/mozilla-test-fail-screenshot_n1bPXJ.png

which happens to be the same failure as this bug:
https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=osx&selectedTaskRun=YGWlyLzkT9W0dM79oWcnvQ.0

I would say maybe test-verify isn't going to give you screenshots, but normal harness failures will. Test-verify could be opening/closing the browser too fast for the screenshot to work (a theory, no real evidence)

Flags: needinfo?(jmaher)

Ok, thanks. I'll keep that in mind and stay clear of TV jobs when I need screenshots.

(In reply to Andreas Pehrson [:pehrsons] from comment #281)

It appears these mac failures are a result of some (?) macs having changed screen resolution from 1280x1024 to 1600x1200 -- I am judging this solely on the captured screenshots.

That means the aspect ratio has changed, and that affects how we scale the screen sharing tracks in the test. We request the screenshare to capture with a width and height between 10 and 100 pixels. It will retain the aspect ratio so these screen resolutions might scale a bit differently. 10 to 100 is quite small and it could be that a tested pixel is close enough to the black sides, or another quadrant, and falls outside the threshold.

When the macs fail we test for green (0, 255, 0) but get (46, 255, 6) with a threshold of 16 (meaning each r,g,b value can be up to 16 off the reference value).

Scaling down to a bit larger resolution than this should help stabilize this test against similar future changes. I don't want to change this too much because it has also helped catch real issues in the past, where perhaps a bar or popup is visible high on the screen and leaks into some of the tested pixels.

It seems like this was not entirely accurate, because the test fails when we're not scaling. Somehow red and blue are within the threshold of 16, but not green. Judging from the screenshot, which seems ever so slightly off color wise, red, green and blue are all fine in the canvas, but not in the video element. There is nothing osbtructing the screenshare images though, so I can only speculatively attribute this to either the capture code or some format conversion code. We do use YUV420 for captured images so I anticipate values being rounded a bit but not really this much.

Anyway, I think the easiest way out is to increase the threshold. Testing that now.

Prior to this patch various failure paths, e.g., runTest() from
mediaStreamPlayback.js would call SimpleTest.finish() twice.

This patch fixes this so no path will call finish only on failure (and not on
success) to make responsibilities clear. This applies to PeerConnectionTest.run
and runTestWhenReady.

runTestWhenReady will be in charge of calling finish for all paths through the
test framework. Its callers runTest and runNetworkTest will stop calling finish.

The responsibility for calling networkTestFinished is moved from
PeerConnectionTest.run to runNetworkTest since the latter calls
startNetworkAndTest which is the analogous start function. At the same time,
networkTestFinished stops calling through to finish since that is now the
responsibility of runTestWhenReady.

All users of the relevant APIs are updated to comply. In many cases related code
is modernized and cleaned up to support the new pattern and to improve
readability.

This does several things, including:

  • Reduces the timeout in case a pixel doesn't match from full test timeout to
    30 seconds.
  • Reduces the log spam when a pixel doesn't match to only write the last color
    checked instead of every check (once per second). This writes the last color
    also when passing for completion in logs.
  • Stops tracks and exits fullscreen before logging a failure, meaning the
    constraints-scaled image becomes visible in the screenshot from try.
  • Increases the size of the video element showing the screensharing video track,
    so that pixel check failures are easy to confirm in screenshots from try.

Hi Andreas, can the patches here be landed or are there any other changes planed?
There are 76 total failures in the last 7 days on

[task 2021-04-05T04:50:45.612Z] 04:50:45 INFO - TEST-START | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html
[task 2021-04-05T04:50:45.639Z] 04:50:45 INFO - GECKO(6063) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2021-04-05T04:50:45.639Z] 04:50:45 INFO - GECKO(6063) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2021-04-05T04:50:45.742Z] 04:50:45 INFO - GECKO(6063) | TEST DEVICES: No test device found in media.audio_loopback_dev, using fake audio streams.
[task 2021-04-05T04:50:45.743Z] 04:50:45 INFO - GECKO(6063) | TEST DEVICES: No test device found in media.video_loopback_dev, using fake video streams.
[task 2021-04-05T04:50:46.472Z] 04:50:46 INFO - GECKO(6063) | 2021-04-05 04:50:46.451 firefox[6063:58548] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
[task 2021-04-05T04:55:49.645Z] 04:55:49 INFO - TEST-INFO | started process screencapture
[task 2021-04-05T04:55:49.775Z] 04:55:49 INFO - TEST-INFO | screencapture: exit 0
[task 2021-04-05T04:55:49.775Z] 04:55:49 INFO - <snipped 1065 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2021-04-05T04:55:49.775Z] 04:55:49 INFO - Buffered messages logged at 04:55:22
[task 2021-04-05T04:55:49.776Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.776Z] 04:55:49 INFO - Buffered messages logged at 04:55:23

[task 2021-04-05T04:55:49.805Z] 04:55:49 INFO - Buffered messages logged at 04:55:48
[task 2021-04-05T04:55:49.805Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.805Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - Buffered messages logged at 04:55:49
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - Buffered messages finished
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - TEST-UNEXPECTED-FAIL | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html | Test timed out.
[task 2021-04-05T04:55:49.806Z] 04:55:49 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-04-05T04:55:49.807Z] 04:55:49 INFO - reportError@https://example.com/tests/SimpleTest/TestRunner.js:147:24
[task 2021-04-05T04:55:49.807Z] 04:55:49 INFO - TestRunner._checkForHangs@https://example.com/tests/SimpleTest/TestRunner.js:170:18
[task 2021-04-05T04:55:49.807Z] 04:55:49 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:50.036Z] 04:55:50 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:50.336Z] 04:55:50 INFO - Checking pixel against green. Got [46,255,6,255] (NO)
[task 2021-04-05T04:55:50.765Z] 04:55:50 INFO - GECKO(6063) | MEMORY STAT | vsize 14847MB | residentFast 134MB | heapAllocated 15MB
[task 2021-04-05T04:55:50.785Z] 04:55:50 INFO - TEST-OK | dom/media/webrtc/tests/mochitests/test_getUserMedia_basicScreenshare.html | took 305182ms
[task 2021-04-05T04:55:50.789Z] 04:55:50 INFO - Checking pixel against green. Got [46,255,6,255] (NO)

Flags: needinfo?(apehrson)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

This can land. Easter holidays...

Flags: needinfo?(apehrson)
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/92396aa42448
Fix failure paths across head.js, mediaStreamPlayback.js and pc.js. r=padenot
https://hg.mozilla.org/integration/autoland/rev/3c00ac9ec33f
Retain newlines when writing stack for errors in head.js. r=padenot
https://hg.mozilla.org/integration/autoland/rev/1157870af3a6
Improve test_gUM_basicScreenshare.html. r=padenot
https://hg.mozilla.org/integration/autoland/rev/dbd6af35dad1
Increase pixel checking threshold. r=padenot
You need to log in before you can comment on or make changes to this bug.