Closed Bug 1714703 Opened 3 years ago Closed 3 years ago

Permanent [Tier 2] components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html | Test timed out. -

Categories

(Core :: Privacy: Anti-Tracking, defect, P5)

Product:
Core
Component:
Privacy: Anti-Tracking
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
91 Branch
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox89 --- unaffected
firefox90 --- unaffected
firefox91 --- fixed

People

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

References

(Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Bug 1714703 - Promisify GamepadServiceTest
48 bytes, text/x-phabricator-request
Details | Review

Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=341813514&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Oske_xhBR1maGahDFvOWBQ/runs/0/artifacts/public/logs/live_backing.log

INFO - TEST-START | components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html
[task 2021-06-04T21:56:56.673Z] 21:56:56     INFO - GECKO(2114) | [Child 2257, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-06-04T21:56:56.782Z] 21:56:56     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:2925
[task 2021-06-04T21:56:56.795Z] 21:56:56     INFO - GECKO(2114) | [Child 2257, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-06-04T21:56:56.821Z] 21:56:56     INFO - GECKO(2114) | [Child 2257, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-06-04T21:56:56.838Z] 21:56:56     INFO - GECKO(2114) | [Child 2383, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:619
[task 2021-06-04T21:56:56.847Z] 21:56:56     INFO - GECKO(2114) | [Child 2264, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-06-04T21:56:56.873Z] 21:56:56     INFO - GECKO(2114) | [Child 2264, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4442
[task 2021-06-04T21:56:56.890Z] 21:56:56     INFO - GECKO(2114) | [Child 2257, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-06-04T21:56:57.028Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: Ignoring duplicate observer.: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:2612
[task 2021-06-04T21:56:57.042Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.062Z] 21:56:57     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.074Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.078Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.081Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.083Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.086Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.096Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.101Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.104Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.109Z] 21:56:57     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.150Z] 21:56:57     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.242Z] 21:56:57     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T21:56:57.783Z] 21:56:57     INFO - GECKO(2114) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp63r2ibux.mozrunner/runtests_leaks_tab_pid2408.log
[task 2021-06-04T21:56:57.784Z] 21:56:57     INFO - GECKO(2114) | [2408, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:254
[task 2021-06-04T21:56:57.848Z] 21:56:57     INFO - GECKO(2114) | [Child 2408, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:619
[task 2021-06-04T21:56:58.279Z] 21:56:58     INFO - GECKO(2114) | JavaScript error: https://example.org/tests/browser/components/resistfingerprinting/test/mochitest/test_hide_gamepad_info_iframe.html, line 32: SecurityError: Navigator.getGamepads: Document's Permission Policy does not allow calling getGamepads() from this context.
[task 2021-06-04T22:01:50.850Z] 22:01:50     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/checkouts/gecko/startupcache/StartupCache.cpp:463
[task 2021-06-04T22:01:50.855Z] 22:01:50     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: 'NS_FAILED(aRv)', file /builds/worker/checkouts/gecko/netwerk/ipc/NeckoParent.cpp:861
[task 2021-06-04T22:01:50.855Z] 22:01:50     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: NS_ENSURE_TRUE(mRequest) failed: file /builds/worker/checkouts/gecko/netwerk/base/nsBaseChannel.cpp:928
[task 2021-06-04T22:02:24.521Z] 22:02:24     INFO - TEST-INFO | started process screentopng
[task 2021-06-04T22:02:24.677Z] 22:02:24     INFO - TEST-INFO | screentopng: exit 0
INFO - TEST-UNEXPECTED-FAIL | components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html | Test timed out. - 
[task 2021-06-04T22:02:25.532Z] 22:02:25     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-04T22:02:25.534Z] 22:02:25     INFO - TEST-UNEXPECTED-FAIL | browser/components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html | [SimpleTest.finish()] No checks actually run. (You need to call ok(), is(), or similar functions at least once.  Make sure you use SimpleTest.waitForExplicitFinish() if you need it.) 
[task 2021-06-04T22:02:25.534Z] 22:02:25     INFO - SimpleTest.ok@https://example.org/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-06-04T22:02:25.534Z] 22:02:25     INFO - afterCleanup@https://example.org/tests/SimpleTest/SimpleTest.js:1423:18
[task 2021-06-04T22:02:25.534Z] 22:02:25     INFO - executeCleanupFunction@https://example.org/tests/SimpleTest/SimpleTest.js:1488:7
[task 2021-06-04T22:02:25.534Z] 22:02:25     INFO - SimpleTest.finish@https://example.org/tests/SimpleTest/SimpleTest.js:1508:3
[task 2021-06-04T22:02:25.534Z] 22:02:25     INFO - @https://example.org/tests/SimpleTest/SimpleTest.js:2148:16
[task 2021-06-04T22:02:25.549Z] 22:02:25     INFO - GECKO(2114) | MEMORY STAT | vsize 2566MB | residentFast 148MB | heapAllocated 7MB
[task 2021-06-04T22:02:25.611Z] 22:02:25     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.618Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.659Z] 22:02:25     INFO - TEST-OK | components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html | took 329015ms
[task 2021-06-04T22:02:25.695Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.698Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.701Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.702Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.702Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.703Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.705Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.706Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.747Z] 22:02:25     INFO - GECKO(2114) | [Parent 2114, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:527
[task 2021-06-04T22:02:25.755Z] 22:02:25     INFO - GECKO(2114) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-04T22:02:25.756Z] 22:02:25     INFO - GECKO(2114) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-06-04T22:02:25.763Z] 22:02:25     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.767Z] 22:02:25     INFO - GECKO(2114) | [Child 2252, Main Thread] WARNING: '!aContent->GetComposedDoc()', file /builds/worker/checkouts/gecko/layout/base/nsCSSFrameConstructor.cpp:8430
[task 2021-06-04T22:02:25.800Z] 22:02:25     INFO - TEST-START | Shutdown
status-firefox89: --- → unaffected
status-firefox90: --- → unaffected
status-firefox91: --- → affected
status-firefox-esr78: --- → unaffected
Flags: needinfo?(marcos)
Keywords: regression
Regressed by: 1704005
Summary: Intermittent [Tier 2] components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html | Test timed out. - → Permanent [Tier 2] components/resistfingerprinting/test/mochitest/test_hide_gamepad_info.html | Test timed out. -
Has Regression Range: --- → yes

Thanks! Having a look.

Flags: needinfo?(marcos)

(Hi Mike! Sorry to ping you on this... need some quick guidance or maybe you can bring in the right people to assist me?)

The issue with the test is that it's going to be flaky because it's (ab)using setTimeout() to simulate waiting.

There is a larger problem that the testing service doesn't use promises for updating or removing things, so setTimeout() was being used to get around that.

A few options:

  1. I rewrite the test, and assume the events will be queued and fire - I just put in a some awaits in place.
  2. We disable or delete this test - not ideal, as it's dealing with Fingerpriting.
  3. Fix the testing service to return a promise that resolves after the events fire.
  4. Do nothing ... it's flaky... sometimes it passes.

Option 3 is ideal, but it's outside the scope of time I can devote to this right now.

Flags: needinfo?(mconley)

s/3. Fix the testing service/3. Fix the Gamepad testing service (GamepadServiceTest.cpp)/

I did a little bit more digging, and option 3 wouldn't be too taxing.

in GamepadTestChannelParent::RecvGamepadTestEvent:
https://searchfox.org/mozilla-central/source/dom/gamepad/ipc/GamepadTestChannelParent.cpp#61

The if statements there would need to be modified to SendReplyGamepadHandle().

Then the appropriate promise would be resolved in void GamepadServiceTest::ReplyGamepadHandle() and removed from the mPromiseList.

It might be nice to treat const GamepadHandle& aHandle as nullable, then one could MaybeResolveAsUndefined() for these other event types.

make GamepadServiceTest's methods return promises, so to avoid testing with flaky setTimeout().

Hi marcos! :)

Certainly #3 sounds the most appealing. I've retriggered the appropriate test on your try build a number of times (M-fis-xorig 12 on Linux 18.04 x64 debug) to see how your change affects it.

Flags: needinfo?(mconley)

Appreciate that! Looks all good (at least, fails are unrelated).

@timhuang, when you are back, could you suggest a reviewer for the patch by chance? It's only small.

Flags: needinfo?(tihuang)

I would recommend @tjr to be the reviewer.

Flags: needinfo?(tihuang)
Assignee: nobody → marcos
Status: NEW → ASSIGNED

Marcos, FYI: this test failure was reproduced when enabling Fission+xorigin mode mochitests on more platforms.

Note that this test is currently disabled for Fission+xorigin mode on all platforms. Once this failure is fixed, the skip-if annotation can be removed in bug 1716401:

[test_hide_gamepad_info.html]
skip-if =
  fission && xorigin  # Bug 1716401 - New fission platform triage

https://searchfox.org/mozilla-central/rev/5e955a47c4af398e2a859b34056017764e7a2252/browser/components/resistfingerprinting/test/mochitest/mochitest.ini#16-18

Flags: needinfo?(marcos)

:cpeterson, sorry for the silly question, I'm a bit out of the loop since leaving Mozilla... locally (or on try), how can I run this patch sufficient times so that I can be sure that it's actually fixing the issue?

Flags: needinfo?(marcos)

(In reply to marcos from comment #13)

:cpeterson, sorry for the silly question, I'm a bit out of the loop since leaving Mozilla... locally (or on try), how can I run this patch sufficient times so that I can be sure that it's actually fixing the issue?

Hi, Marcos, thanks for your help with this issue!

First, you will also want to make sure you are running the test with both Fission and "xorigin" test mode enabled. I think mach mochitest --enable-fission --enable-xorigin-tests will do that.

Here are some docs for debugging intermittent test failures:

https://firefox-source-docs.mozilla.org/devtools/tests/debugging-intermittents.html#reproducing-test-failures-locally

Some tips from that page:

You can use the --repeat and --run-until-failure flags to mach mochitest to automate this a bit. It’s nice to do this sort of thing in headless mode (--headless).

Because intermittents are often caused by race conditions, it’s sometimes useful to enable Chaos Mode. This changes timings and event orderings a bit. The simplest way to do this is to enable it in a specific test, by calling SimpleTest.testInChaosMode. You can also set the MOZ_CHAOSMODE environment variable, or even edit mfbt/ChaosMode.cpp directly.

One thing you can do is push to try, and then retrigger the job many times in treeherder
Here is a recent test failure on try:

https://treeherder.mozilla.org/jobs?repo=mozilla-central&revision=206721f8064a145ddb526eb9c50285fd274e7d87&selectedTaskRun=MyDdbLgRTT2iLLwxfGtGmA.0

You can click on one of the orange failed tests on the right and then click the "Retrigger job" 🔄 button (in the lower left panel) multiple times to rerun the same test.

Flags: needinfo?(marcos)
Pushed by marcos@marcosc.com:
https://hg.mozilla.org/integration/autoland/rev/8742cb4bb4be
Promisify GamepadServiceTest r=tjr,peterv

https://hg.mozilla.org/mozilla-central/rev/8742cb4bb4be

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox91: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 91 Branch
See Also: → 1716407

Thanks for the heads up, Chris! will try to come back to these this week. We should hopefully know by then if the updated gamepad testing service helped.

(intentionally leaving NI on my self to come back to this)

Experimenting revealed that Permission Policy doesn't work when fission is enabled. Asked Baku for info in:
https://bugzilla.mozilla.org/show_bug.cgi?id=1716407#c6

Flags: needinfo?(marcos)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: