1575553 - Perma [tier2] browser/components/resistfingerprinting/test/browser/browser_navigator.js | Test timed out -

Status: RESOLVED WORKSFORME

(Core :: Security, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=262660360&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/EkB4p7qPROy8jxUteqv1cA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-08-21T12:35:53.517Z] 12:35:53     INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.product reports correct constant value. - 
[task 2019-08-21T12:35:53.518Z] 12:35:53     INFO - Leaving test bound runWorkerNavigatorTest
[task 2019-08-21T12:35:53.518Z] 12:35:53     INFO - Entering test bound runOverrideTest
[task 2019-08-21T12:35:53.519Z] 12:35:53     INFO - Console message: [JavaScript Error: "NS_ERROR_UNEXPECTED: " {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 2684}]
[task 2019-08-21T12:35:53.522Z] 12:35:53     INFO - Buffered messages finished
[task 2019-08-21T12:35:53.523Z] 12:35:53     INFO - TEST-UNEXPECTED-FAIL | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Test timed out - 
[task 2019-08-21T12:35:53.523Z] 12:35:53     INFO - GECKO(9907) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-08-21T12:35:53.524Z] 12:35:53     INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-08-21T12:35:53.524Z] 12:35:53     INFO - GECKO(9907) | MEMORY STAT | vsize 2934MB | residentFast 286MB | heapAllocated 97MB
[task 2019-08-21T12:35:53.525Z] 12:35:53     INFO - TEST-OK | browser/components/resistfingerprinting/test/browser/browser_navigator.js | took 45030ms
[task 2019-08-21T12:35:53.527Z] 12:35:53     INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-08-21T12:35:53.527Z] 12:35:53     INFO - TEST-UNEXPECTED-FAIL | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Found a tab after previous test timed out: about:blank - 
[task 2019-08-21T12:35:53.528Z] 12:35:53    ERROR - GECKO(9907) | TEST-UNEXPECTED-FAIL | unknown test url | uncaught exception - TypeError: initialBrowser.frameLoader.remoteTab is null at AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:167:1
[task 2019-08-21T12:35:53.529Z] 12:35:53     INFO - GECKO(9907) | _getSwitcher@chrome://browser/content/tabbrowser.js:4705:26
[task 2019-08-21T12:35:53.529Z] 12:35:53     INFO - GECKO(9907) | updateCurrentBrowser@chrome://browser/content/tabbrowser.js:1019:16
[task 2019-08-21T12:35:53.530Z] 12:35:53     INFO - GECKO(9907) | _setupEventListeners/<@chrome://browser/content/tabbrowser.js:5107:16
[task 2019-08-21T12:35:53.530Z] 12:35:53     INFO - GECKO(9907) | set selectedIndex@chrome://global/content/elements/tabbox.js:208:14
[task 2019-08-21T12:35:53.533Z] 12:35:53     INFO - GECKO(9907) | set selectedPanel@chrome://global/content/elements/tabbox.js:227:7
[task 2019-08-21T12:35:53.534Z] 12:35:53     INFO - GECKO(9907) | set selectedIndex@chrome://global/content/elements/tabbox.js:571:11
[task 2019-08-21T12:35:53.534Z] 12:35:53     INFO - GECKO(9907) | set selectedItem@chrome://global/content/elements/tabbox.js:591:35
[task 2019-08-21T12:35:53.535Z] 12:35:53     INFO - GECKO(9907) | set selectedTab@chrome://global/content/elements/tabbox.js:98:11
[task 2019-08-21T12:35:53.535Z] 12:35:53     INFO - GECKO(9907) | set selectedTab@chrome://browser/content/tabbrowser.js:312:7
[task 2019-08-21T12:35:53.537Z] 12:35:53     INFO - GECKO(9907) | _blurTab@chrome://browser/content/tabbrowser.js:3655:31
[task 2019-08-21T12:35:53.538Z] 12:35:53     INFO - GECKO(9907) | _beginRemoveTab@chrome://browser/content/tabbrowser.js:3309:12
[task 2019-08-21T12:35:53.538Z] 12:35:53     INFO - GECKO(9907) | removeTab@chrome://browser/content/tabbrowser.js:3193:15
[task 2019-08-21T12:35:53.539Z] 12:35:53     INFO - GECKO(9907) | Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:708:18
[task 2019-08-21T12:35:53.539Z] 12:35:53     INFO - GECKO(9907) | nextTest@chrome://mochikit/content/browser-test.js:1109:10
[task 2019-08-21T12:35:53.541Z] 12:35:53     INFO - GECKO(9907) | async*timeoutFn@chrome://mochikit/content/browser-test.js:1471:18
[task 2019-08-21T12:35:53.542Z] 12:35:53     INFO - GECKO(9907) | setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1418:80
[task 2019-08-21T12:35:53.543Z] 12:35:53     INFO - GECKO(9907) | nextTest/<@chrome://mochikit/content/browser-test.js:1213:14
[task 2019-08-21T12:35:53.543Z] 12:35:53     INFO - GECKO(9907) | SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67
[task 2019-08-21T12:35:53.544Z] 12:35:53     INFO - GECKO(9907) | JavaScript error: resource:///modules/AsyncTabSwitcher.jsm, line 167: TypeError: initialBrowser.frameLoader.remoteTab is null
[task 2019-08-21T12:35:53.544Z] 12:35:53     INFO - GECKO(9907) | JavaScript error: chrome://browser/content/parent/ext-browser.js, line 502: TypeError: currentTab.linkedBrowser is null
[task 2019-08-21T12:35:53.547Z] 12:35:53     INFO - Console message: [JavaScript Error: "TypeError: initialBrowser.frameLoader.remoteTab is null" {file: "resource:///modules/AsyncTabSwitcher.jsm" line: 167}]

Comment 1

[Daniel Varga [:dvarga]]

:kmag could this be related with your push?

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&selectedJob=262679005&searchStr=m-fis%28bc6%29&revision=1f836a6215abeb7a22c4225b4967bc8326cf6bb9

Comment 2

[Kris Maglione [:kmag]]

It's not impossible, but I doubt it. This is failing in the process switching code, which shouldn't have been affected by those changes. They may have exacerbated an existing race, though.

Comment 3

[Intermittent Failures Robot]

29 failures in 952 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 17
• try: 12

Platform breakdown:

• linux64: 11
• windows10-64-qr: 8
• windows10-64: 8
• windows7-32: 1
• linux64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1575553&startday=2019-08-22&endday=2019-08-22&tree=all

Comment 4

[Intermittent Failures Robot]

26 failures in 813 pushes (0.032 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 20
• mozilla-central: 6

Platform breakdown:

• linux64: 10
• windows10-64: 8
• windows10-64-qr: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1575553&startday=2019-08-23&endday=2019-08-23&tree=all

Comment 5

[Intermittent Failures Robot]

96 failures in 5073 pushes (0.019 failures/push) were associated with this bug in the last 7 days.

This is the #18 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 44
• mozilla-inbound: 14
• try: 34
• autoland: 4

Platform breakdown:

• linux64: 51
• windows10-64: 22
• windows10-64-qr: 21
• windows7-32: 1
• linux64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1575553&startday=2019-08-19&endday=2019-08-25&tree=all

Comment 6

[Andreea Pavel [:apavel]]

Hi Andrew, can this be from bug 1574567?

There are 65 total failures in the last 7 days on windows10-64-qr opt, windows10-64 opt, linux64 opt and debug

Recent failure log:

[task 2019-08-28T01:57:36.239Z] 01:57:36 INFO - TEST-START | browser/components/resistfingerprinting/test/browser/browser_navigator.js
[task 2019-08-28T01:57:37.628Z] 01:57:37 INFO - GECKO(11810) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-08-28T01:57:37.665Z] 01:57:37 INFO - GECKO(11810) | JavaScript error: resource:///actors/AboutReaderChild.jsm, line 95: NS_ERROR_UNEXPECTED:
[task 2019-08-28T01:57:37.665Z] 01:57:37 INFO - GECKO(11810) | ###!!! [Child][MessageChannel] Error: (msgtype=0x570005,name=PHttpChannel::Msg_Cancel) Closed channel: cannot send/recv
[task 2019-08-28T01:57:37.665Z] 01:57:37 INFO - GECKO(11810) | ###!!! [Child][MessageChannel] Error: (msgtype=0x370124,name=PContent::Msg_DetachBrowsingContext) Closed channel: cannot send/recv
[task 2019-08-28T01:57:37.665Z] 01:57:37 INFO - GECKO(11810) | JavaScript error: resource:///modules/sessionstore/SessionStore.jsm, line 2684: NS_ERROR_UNEXPECTED:
[task 2019-08-28T01:57:37.942Z] 01:57:37 INFO - GECKO(11810) | Assertion failure
[task 2019-08-28T01:57:37.942Z] 01:57:37 INFO - GECKO(11810) | assert@resource:///modules/AsyncTabSwitcher.jsm:490:36
[task 2019-08-28T01:57:37.943Z] 01:57:37 INFO - GECKO(11810) | finish@resource:///modules/AsyncTabSwitcher.jsm:330:10
[task 2019-08-28T01:57:37.944Z] 01:57:37 INFO - GECKO(11810) | postActions@resource:///modules/AsyncTabSwitcher.jsm:688:12
[task 2019-08-28T01:57:37.944Z] 01:57:37 INFO - GECKO(11810) | handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1148:12
[task 2019-08-28T01:57:37.944Z] 01:57:37 INFO - GECKO(11810) | EventListener.handleEventAsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:155:17
[task 2019-08-28T01:57:37.944Z] 01:57:37 INFO - GECKO(11810) | _getSwitcher@chrome://browser/content/tabbrowser.js:4705:26
[task 2019-08-28T01:57:37.945Z] 01:57:37 INFO - GECKO(11810) | updateCurrentBrowser@chrome://browser/content/tabbrowser.js:1019:16
[task 2019-08-28T01:57:37.946Z] 01:57:37 INFO - GECKO(11810) | _setupEventListeners/<@chrome://browser/content/tabbrowser.js:5107:16
[task 2019-08-28T01:57:37.946Z] 01:57:37 INFO - GECKO(11810) | set selectedIndex@chrome://global/content/elements/tabbox.js:208:14
[task 2019-08-28T01:57:37.947Z] 01:57:37 INFO - GECKO(11810) | set selectedPanel@chrome://global/content/elements/tabbox.js:227:7
[task 2019-08-28T01:57:37.947Z] 01:57:37 INFO - GECKO(11810) | set selectedIndex@chrome://global/content/elements/tabbox.js:571:11
[task 2019-08-28T01:57:37.948Z] 01:57:37 INFO - GECKO(11810) | set selectedItem@chrome://global/content/elements/tabbox.js:591:35
[task 2019-08-28T01:57:37.948Z] 01:57:37 INFO - GECKO(11810) | set selectedTab@chrome://global/content/elements/tabbox.js:98:11
[task 2019-08-28T01:57:37.949Z] 01:57:37 INFO - GECKO(11810) | set selectedTab@chrome://browser/content/tabbrowser.js:312:7
[task 2019-08-28T01:57:37.949Z] 01:57:37 INFO - GECKO(11810) | openNewForegroundTab/promises<@resource://testing-common/BrowserTestUtils.jsm:242:61
[task 2019-08-28T01:57:37.949Z] 01:57:37 INFO - GECKO(11810) | switchTab@resource://testing-common/BrowserTestUtils.jsm:350:10
[task 2019-08-28T01:57:37.950Z] 01:57:37 INFO - GECKO(11810) | openNewForegroundTab@resource://testing-common/BrowserTestUtils.jsm:237:26
[task 2019-08-28T01:57:37.950Z] 01:57:37 INFO - GECKO(11810) | testNavigator@chrome://mochitests/content/browser/browser/components/resistfingerprinting/test/browser/browser_navigator.js:92:36
[task 2019-08-28T01:57:37.951Z] 01:57:37 INFO - GECKO(11810) | runOverrideTest@chrome://mochitests/content/browser/browser/components/resistfingerprinting/test/browser/browser_navigator.js:272:9
[task 2019-08-28T01:57:37.951Z] 01:57:37 INFO - GECKO(11810) | AsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1350:34
[task 2019-08-28T01:57:37.951Z] 01:57:37 INFO - GECKO(11810) | async*Tester_execTest@chrome://mochikit/content/browser-test.js:1385:11
[task 2019-08-28T01:57:37.952Z] 01:57:37 INFO - GECKO(11810) | nextTest/<@chrome://mochikit/content/browser-test.js:1213:14
[task 2019-08-28T01:57:37.953Z] 01:57:37 INFO - GECKO(11810) | SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:805:67
[task 2019-08-28T01:58:21.247Z] 01:58:21 INFO - TEST-INFO | started process screentopng
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-INFO | screentopng: exit 0
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - Buffered messages logged at 01:57:36
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - Entering test bound setup
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - Leaving test bound setup
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - Entering test bound runNavigatorTest
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.appName is correctly spoofed. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.appVersion is correctly spoofed. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.platform is correctly spoofed. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.userAgent is correctly spoofed. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.mimeTypes has a length of 0. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.plugins has a length of 0. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.oscpu is correctly spoofed. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.hardwareConcurrency is correctly spoofed. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.appCodeName reports correct constant value. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.product reports correct constant value. -
[task 2019-08-28T01:58:21.710Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.productSub reports correct constant value. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.vendor reports correct constant value. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.vendorSub reports correct constant value. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - Leaving test bound runNavigatorTest
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - Entering test bound runHTTPHeaderTest
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - Buffered messages logged at 01:57:37
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | User Agent HTTP Header is correctly spoofed. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - Leaving test bound runHTTPHeaderTest
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - Entering test bound runWorkerNavigatorTest
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.appName is correctly spoofed. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.appVersion is correctly spoofed. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.platform is correctly spoofed. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.userAgent is correctly spoofed. -
[task 2019-08-28T01:58:21.711Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.hardwareConcurrency is correctly spoofed. -
[task 2019-08-28T01:58:21.712Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.appCodeName reports correct constant value. -
[task 2019-08-28T01:58:21.712Z] 01:58:21 INFO - TEST-PASS | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Navigator.product reports correct constant value. -
[task 2019-08-28T01:58:21.712Z] 01:58:21 INFO - Leaving test bound runWorkerNavigatorTest
[task 2019-08-28T01:58:21.712Z] 01:58:21 INFO - Entering test bound runOverrideTest
[task 2019-08-28T01:58:21.712Z] 01:58:21 INFO - Console message: [JavaScript Error: "NS_ERROR_UNEXPECTED: " {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 2684}]
[task 2019-08-28T01:58:21.712Z] 01:58:21 INFO - Buffered messages finished
[task 2019-08-28T01:58:21.713Z] 01:58:21 INFO - TEST-UNEXPECTED-FAIL | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Test timed out -
[task 2019-08-28T01:58:21.713Z] 01:58:21 INFO - GECKO(11810) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-08-28T01:58:21.714Z] 01:58:21 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-08-28T01:58:21.714Z] 01:58:21 INFO - GECKO(11810) | MEMORY STAT | vsize 2943MB | residentFast 287MB | heapAllocated 96MB
[task 2019-08-28T01:58:21.715Z] 01:58:21 INFO - TEST-OK | browser/components/resistfingerprinting/test/browser/browser_navigator.js | took 45022ms
[task 2019-08-28T01:58:21.716Z] 01:58:21 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-08-28T01:58:21.716Z] 01:58:21 INFO - TEST-UNEXPECTED-FAIL | browser/components/resistfingerprinting/test/browser/browser_navigator.js | Found a tab after previous test timed out: about:blank -
[task 2019-08-28T01:58:21.717Z] 01:58:21 ERROR - GECKO(11810) | TEST-UNEXPECTED-FAIL | unknown test url | uncaught exception - TypeError: initialBrowser.frameLoader.remoteTab is null at AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:167:1

Thanks.

Comment 7

[Andrew McCreight [:mccr8]]

Bug 1574567 only enabled some tests, and not in that directory. It was also backed out on the 19th.

Comment 8

[Andrew McCreight [:mccr8]]

It looks like this test got disabled for Fission in bug 1576814.

Comment 9

[Andreea Pavel [:apavel]]

Thank you.

Comment 10

[Intermittent Failures Robot]

27 failures in 5047 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 25
• try: 2

Platform breakdown:

• linux64: 11
• windows10-64-qr: 9
• windows10-64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1575553&startday=2019-08-26&endday=2019-09-01&tree=all