1485464 - Intermittent browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Uncaught exception - Should open about:preferences. - timed out after 50 tries.

Status: RESOLVED INCOMPLETE

(Firefox :: Settings UI, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=195337928&repo=autoland

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

10:55:53     INFO - Console message: [JavaScript Error: "Invalid string label"]
10:55:53     INFO - Buffered messages finished
10:55:53     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Uncaught exception - Should open about:preferences. - timed out after 50 tries.
10:55:53     INFO - Leaving test bound testOpenPreferencesFromAddBlockingButtons
10:55:53     INFO - Entering test bound cleanup
10:55:53     INFO - Leaving test bound cleanup
10:55:53     INFO - GECKO(2035) | MEMORY STAT | vsize 4407MB | residentFast 422MB | heapAllocated 138MB
10:55:53     INFO - TEST-OK | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | took 45123ms
10:55:53     INFO - Not taking screenshot here: see the one that was previously logged
10:55:53     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Found an unexpected tab at the end of test run: about:preferences#privacy-trackingprotection - 
10:55:53     INFO - Not taking screenshot here: see the one that was previously logged
10:55:53     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Found an unexpected tab at the end of test run: http://tracking.example.org/browser/browser/base/content/test/trackingUI/trackingPage.html - 
10:55:53     INFO - GECKO(2035) | ++DOCSHELL 0x110924800 == 1 [pid = 2039] [id = {9fd97478-e2f5-264f-92f1-fb289028f415}]
10:55:53     INFO - GECKO(2035) | ++DOMWINDOW == 1 (0x120823a00) [pid = 2039] [serial = 27] [outer = 0x0]
10:55:54     INFO - GECKO(2035) | ++DOMWINDOW == 2 (0x1181ed400) [pid = 2039] [serial = 28] [outer = 0x120823a00]
10:55:54     INFO - checking window state

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

10:55:53     INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | The trackingprotection section is spotlighted. - "trackingprotection" == "trackingprotection" - 
10:55:53     INFO - Buffered messages logged at 10:55:41
10:55:53     INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Button is shown. - 
10:55:53     INFO - Buffered messages logged at 10:55:43
10:55:53     INFO - Console message: [JavaScript Error: "Invalid string label"]
10:55:53     INFO - Buffered messages finished
10:55:53     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Uncaught exception - Should open about:preferences. - timed out after 50 tries.

Comment 2

[Intermittent Failures Robot]

1 failures in 2568 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 3

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 4

[Raul Gurzau (:RaulG)]

Failure reoccurred here: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=234664891&repo=mozilla-central&lineNumber=5893

[task 2019-03-18T23:13:24.234Z] 23:13:24 INFO - Console message: [JavaScript Warning: "The resource at “http://trackertest.org/” was blocked because content blocking is enabled." {file: "http://tracking.example.org/browser/browser/base/content/test/trackingUI/trackingPage.html" line: 0}]
[task 2019-03-18T23:13:24.236Z] 23:13:24 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | TP category item is visible -
[task 2019-03-18T23:13:24.236Z] 23:13:24 INFO - Buffered messages logged at 23:13:18
[task 2019-03-18T23:13:24.237Z] 23:13:24 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Trackers view was shown -
[task 2019-03-18T23:13:24.238Z] 23:13:24 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | The preferences button is shown. -
[task 2019-03-18T23:13:24.238Z] 23:13:24 INFO - Buffered messages finished
[task 2019-03-18T23:13:24.239Z] 23:13:24 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Uncaught exception - Should open about:preferences. - timed out after 50 tries.
[task 2019-03-18T23:13:24.239Z] 23:13:24 INFO - Leaving test bound testOpenPreferencesFromTrackersSubview
[task 2019-03-18T23:13:24.241Z] 23:13:24 INFO - Entering test bound testOpenPreferencesFromCookiesSubview
[task 2019-03-18T23:13:24.241Z] 23:13:24 INFO - GECKO(2657) | ++DOCSHELL 0xe543d000 == 2 [pid = 2858] [id = {02254d77-f1c5-45f4-b792-471065db8d24}]
[task 2019-03-18T23:13:24.242Z] 23:13:24 INFO - GECKO(2657) | ++DOMWINDOW == 3 (0xe7231020) [pid = 2858] [serial = 97] [outer = (nil)]
[task 2019-03-18T23:13:24.242Z] 23:13:24 INFO - GECKO(2657) | ++DOMWINDOW == 4 (0xe543f000) [pid = 2858] [serial = 98] [outer = 0xe7231020]
[task 2019-03-18T23:13:24.243Z] 23:13:24 INFO - GECKO(2657) | ++DOMWINDOW == 5 (0xe5440800) [pid = 2858] [serial = 99] [outer = 0xe7231020]
[task 2019-03-18T23:13:24.392Z] 23:13:24 INFO - GECKO(2657) | ++DOCSHELL 0xe729c800 == 3 [pid = 2858] [id = {527509f8-4155-434d-a8cd-4e22af8050ca}]
[task 2019-03-18T23:13:24.393Z] 23:13:24 INFO - GECKO(2657) | ++DOMWINDOW == 6 (0xe7231350) [pid = 2858] [serial = 100] [outer = (nil)]
[task 2019-03-18T23:13:24.420Z] 23:13:24 INFO - GECKO(2657) | --DOMWINDOW == 30 (0xdcfdd800) [pid = 2657] [serial = 34] [outer = (nil)] [url = about:blank]
[task 2019-03-18T23:13:24.422Z] 23:13:24 INFO - GECKO(2657) | --DOMWINDOW == 29 (0xde0f0c00) [pid = 2657] [serial = 38] [outer = (nil)] [url = about:blank]
[task 2019-03-18T23:13:24.422Z] 23:13:24 INFO - GECKO(2657) | --DOMWINDOW == 28 (0xde0f1400) [pid = 2657] [serial = 39] [outer = (nil)] [url = about:blank]
[task 2019-03-18T23:13:24.498Z] 23:13:24 INFO - GECKO(2657) | ++DOMWINDOW == 7 (0xe5441000) [pid = 2858] [serial = 101] [outer = 0xe7231350]
[task 2019-03-18T23:13:24.581Z] 23:13:24 INFO - GECKO(2657) | [Parent 2657, Main Thread] WARNING: '!mPresContext', file /builds/worker/workspace/build/src/dom/events/UIEvent.cpp, line 165
[task 2019-03-18T23:13:24.582Z] 23:13:24 INFO - GECKO(2657) | [Parent 2657, Main Thread] WARNING: '!mPresContext', file /builds/worker/workspace/build/src/dom/events/UIEvent.cpp, line 179
[task 2019-03-18T23:13:24.833Z] 23:13:24 INFO - Console message: [JavaScript Warning: "The resource at “http://trackertest.org/” was blocked because content blocking is enabled." {file: "http://tracking.example.org/browser/browser/base/content/test/trackingUI/trackingPage.html" line: 0}]
[task 2019-03-18T23:13:24.876Z] 23:13:24 INFO - GECKO(2657) | --DOMWINDOW == 6 (0xe7231240) [pid = 2858] [serial = 94] [outer = (nil)] [url = https://example.com/]
[task 2019-03-18T23:13:24.876Z] 23:13:24 INFO - GECKO(2657) | --DOCSHELL 0xe5449400 == 2 [pid = 2858] [id = {65ba2ac5-f334-4bea-a4ce-d350018667f2}] [url = https://example.com/]
[task 2019-03-18T23:13:24.974Z] 23:13:24 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | TP category item is visible -
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - Stack trace:
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochikit/content/browser-test.js:test_ok:1304
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochitests/content/browser/browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js:testOpenPreferencesFromCookiesSubview/<:138
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - resource://testing-common/BrowserTestUtils.jsm:withNewTab:111
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochitests/content/browser/browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js:testOpenPreferencesFromCookiesSubview:131
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1134
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2019-03-18T23:13:24.975Z] 23:13:24 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803

Comment 5

[Intermittent Failures Robot]

63 failures in 2561 pushes (0.025 failures/push) were associated with this bug in the last 7 days.

This is the #39 most frequent failure this week.

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

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

Repository breakdown:

• mozilla-central: 39
• autoland: 13
• mozilla-inbound: 7
• try: 4

Platform breakdown:

• linux32: 19
• linux64-ccov: 18
• windows10-64-ccov: 17
• linux64: 4
• osx-10-10: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1485464&startday=2019-03-18&endday=2019-03-24&tree=all

Comment 6

[Cristina Coroiu [:ccoroiu]]

In the last 7 days, there have been 65 failures.

The failures are on linux32, linux64, linux64-ccov, osx-10-10 and windows10-64-ccov.
Affected build type: debug.

An example of a recent log file: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236259886&repo=mozilla-inbound&lineNumber=4430

And the relevant part of the log:
[task 2019-03-27T00:25:44.123Z] 00:25:44 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | The preferences button is shown. -
[task 2019-03-27T00:25:44.125Z] 00:25:44 INFO - Buffered messages finished
[task 2019-03-27T00:25:44.126Z] 00:25:44 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Uncaught exception - Should open about:preferences. - timed out after 50 tries.
[task 2019-03-27T00:25:44.127Z] 00:25:44 INFO - Leaving test bound testOpenPreferencesFromCookiesSubview
[task 2019-03-27T00:25:44.128Z] 00:25:44 INFO - GECKO(1796) | MEMORY STAT | vsize 733MB | residentFast 364MB | heapAllocated 134MB
[task 2019-03-27T00:25:44.129Z] 00:25:44 INFO - TEST-OK | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | took 24854ms
[task 2019-03-27T00:25:44.131Z] 00:25:44 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-03-27T00:25:44.132Z] 00:25:44 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Found an unexpected tab at the end of test run: about:preferences#privacy-trackingprotection -
[task 2019-03-27T00:25:44.135Z] 00:25:44 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-03-27T00:25:44.136Z] 00:25:44 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_open_preferences.js | Found an unexpected tab at the end of test run: http://tracking.example.org/browser/browser/base/content/test/trackingUI/trackingPage.html -
[task 2019-03-27T00:25:44.136Z] 00:25:44 INFO - GECKO(1796) | ++DOCSHELL 0xde5a1000 == 2 [pid = 1867] [id = {80d35f86-c7bb-40e2-9111-ab6052913243}]
[task 2019-03-27T00:25:44.137Z] 00:25:44 INFO - GECKO(1796) | ++DOMWINDOW == 4 (0xf7168ac0) [pid = 1867] [serial = 73] [outer = (nil)]
[task 2019-03-27T00:25:44.138Z] 00:25:44 INFO - GECKO(1796) | ++DOMWINDOW == 5 (0xde5a2c00) [pid = 1867] [serial = 74] [outer = 0xf7168ac0]
[task 2019-03-27T00:25:44.139Z] 00:25:44 INFO - GECKO(1796) | ++DOMWINDOW == 6 (0xde5a8400) [pid = 1867] [serial = 75] [outer = 0xf7168ac0]
[task 2019-03-27T00:25:44.168Z] 00:25:44 INFO - GECKO(1796) | ++DOMWINDOW == 7 (0xde5aa400) [pid = 1867] [serial = 76] [outer = 0xf7168ac0]
[task 2019-03-27T00:25:44.183Z] 00:25:44 INFO - checking window state
[task 2019-03-27T00:25:44.200Z] 00:25:44 INFO - GECKO(1796) | [Parent 1796, Main Thread] WARNING: NS_ENSURE_TRUE(scriptGlobalObject) failed: file /builds/worker/workspace/build/src/dom/prototype/PrototypeDocumentContentSink.cpp, line 946
[task 2019-03-27T00:25:44.200Z] 00:25:44 INFO - GECKO(1796) | [Parent 1796, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8000FFFF: file /builds/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 374
[task 2019-03-27T00:25:44.207Z] 00:25:44 INFO - GECKO(1796) | [Parent 1796, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8000FFFF: file /builds/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 374
[task 2019-03-27T00:25:44.211Z] 00:25:44 INFO - GECKO(1796) | JavaScript error: chrome://browser/content/preferences/in-content/preferences.js, line 83: ReferenceError: gSyncPane is not defined
[task 2019-03-27T00:25:44.279Z] 00:25:44 INFO - GECKO(1796) | --DOMWINDOW == 40 (0xe0af1c00) [pid = 1796] [serial = 24] [outer = (nil)] [url = about:preferences#privacy-trackingprotection]

Johann, as you are the triage owner of this component, could you please take a look at this?
Thank you!

Comment 7

[Intermittent Failures Robot]

15 failures in 557 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 12
• autoland: 2
• mozilla-inbound: 1

Platform breakdown:

• linux64-ccov: 10
• windows10-64-ccov: 2
• linux32: 3

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

Comment 8

[Intermittent Failures Robot]

77 failures in 3910 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #30 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: 61
• autoland: 12
• mozilla-inbound: 2
• try: 2

Platform breakdown:

• linux64-ccov: 32
• windows10-64-ccov: 26
• linux64: 2
• linux32: 17

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

Comment 9

[Johann Hofmann [:johannh]]

From a quick look it seems like the test does things correctly but then about:preferences#privacy-permissions doesn't load and there's a JS error logged that says Invalid string label.

Jared, does that sound familiar to you? Could any recent work have caused this?

Cristina, can we figure out a regression range for when the intermittent started showing up?

I'm quite busy right now so I can't promise to look into it quickly, but I'll keep an eye on it.

Comment 10

[Cristina Coroiu [:ccoroiu]]

Johann, from 17th of March this failed appeared, as you can see on the graph: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-03-04&endday=2019-04-03&tree=trunk&bug=1485464

Started with this merge: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=fe798624cda039ae74289929e35487560d354db2&selectedJob=234664891

Comment 11

[Johann Hofmann [:johannh]]

Thanks! Not sure what to make of that range, though :/

Comment 12

[Jared Wein [:jaws] (please needinfo? me)]

The Invalid string label is happening because the origin of "identityPopup-permissions-PreferencesButton" is specified but it's not listed in the list of origins at https://searchfox.org/mozilla-central/source/toolkit/components/telemetry/Histograms.json#6507,6513

The subcategory looks fine. The uncaught exception in this case is likely the issue here, but I don't know why this is only intermittent then.

Comment 13

[Johann Hofmann [:johannh]]

Ok so this depends on bug 1494948, then. I'll try to check with the assignee if we can expedite that bug...

Comment 14

[Intermittent Failures Robot]

33 failures in 2843 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 24
• mozilla-inbound: 2
• autoland: 4
• try: 1
• mozilla-beta: 2

Platform breakdown:

• linux64-ccov: 16
• windows10-64-ccov: 8
• osx-10-10: 4
• linux32: 5

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

Comment 15

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup