1701732 - Intermittent browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Test timed out -

Status: RESOLVED INCOMPLETE

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=334789715&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZwfhSknkRlWCT5rF9qyp4Q/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZwfhSknkRlWCT5rF9qyp4Q/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2021-03-29T16:12:17.636Z] 16:12:17     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine is Bing - 
[task 2021-03-29T16:12:17.637Z] 16:12:17     INFO - Buffered messages logged at 16:11:03
[task 2021-03-29T16:12:17.637Z] 16:12:17     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine is Bing - 
[task 2021-03-29T16:12:17.637Z] 16:12:17     INFO - Buffered messages finished
[task 2021-03-29T16:12:17.641Z] 16:12:17     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Test timed out - 
[task 2021-03-29T16:12:17.641Z] 16:12:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-03-29T16:12:17.642Z] 16:12:17     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Extension left running at test shutdown - 
[task 2021-03-29T16:12:17.643Z] 16:12:17     INFO - Stack trace:
[task 2021-03-29T16:12:17.643Z] 16:12:17     INFO - chrome://mochikit/content/browser-test.js:test_ok:1331
[task 2021-03-29T16:12:17.644Z] 16:12:17     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:117
[task 2021-03-29T16:12:17.644Z] 16:12:17     INFO - chrome://mochikit/content/browser-test.js:nextTest:571
[task 2021-03-29T16:12:17.644Z] 16:12:17     INFO - GECKO(3804) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2021-03-29T16:12:17.644Z] 16:12:17     INFO - GECKO(3804) | MEMORY STAT | vsize 3358MB | residentFast 504MB | heapAllocated 217MB
[task 2021-03-29T16:12:17.645Z] 16:12:17     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | took 90324ms
[task 2021-03-29T16:12:17.652Z] 16:12:17     INFO - GECKO(3804) | [Child 3872: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f5c8c8d3c00 == 1 [pid = 3872] [id = 2]
[task 2021-03-29T16:12:17.652Z] 16:12:17     INFO - GECKO(3804) | [Child 3872: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f5ca9263ac0) [pid = 3872] [serial = 8] [outer = 0]
[task 2021-03-29T16:12:17.652Z] 16:12:17     INFO - GECKO(3804) | [Child 3872: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f5c8c8d5000) [pid = 3872] [serial = 9] [outer = 7f5ca9263ac0]
[task 2021-03-29T16:12:17.748Z] 16:12:17     INFO - checking window state
[task 2021-03-29T16:12:17.869Z] 16:12:17     INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js
[task 2021-03-29T16:12:19.180Z] 16:12:19     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Buffered messages logged at 16:12:17
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Entering test bound setup
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Leaving test bound setup
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Entering test bound test_extension_setting_default_engine
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Extension loaded
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Buffered messages logged at 16:12:18
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Search provider extension should be running - "running" == "running" - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Extension ID of search provider should be set - "79782ab1c1a68665b8411d88f148d15c65d1377c@temporary-addon" == true - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine is DuckDuckGo - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine is Google - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Leaving test bound test_extension_setting_default_engine
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Entering test bound test_extension_setting_default_engine_hidden
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Extension loaded
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Search provider extension should be running - "running" == "running" - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Extension ID of search provider should be set - "79782ab1c1a68665b8411d88f148d15c65d1377c@temporary-addon" == true - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine should have remained as the default - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | The extension should not have been recorded as having set the default search - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine is Google - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Leaving test bound test_extension_setting_default_engine_hidden
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Entering test bound test_extension_setting_default_engine_external
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Extension loaded
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Buffered messages finished
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | uncaught exception - ReferenceError: ok is not defined at popupshown@chrome://mochitests/content/browser/browser/components/extensions/test/browser/head.js:194:7
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - 
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - Stack trace:
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:simpletestOnerror:2112
[task 2021-03-29T16:12:19.182Z] 16:12:19     INFO - GECKO(3804) | JavaScript error: chrome://mochitests/content/browser/browser/components/extensions/test/browser/head.js, line 194: ReferenceError: ok is not defined
[task 2021-03-29T16:12:19.185Z] 16:12:19     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | addon-webext-defaultsearch notification shown - ```

Comment 1

[Alexandru Michis [:malexandru]]

Started appearing on tier 1 jobs:
https://treeherder.mozilla.org/logviewer?job_id=334817122&repo=autoland&lineNumber=30609

Shane, could this be caused by the changes in Bug 1646338?

Comment 2

[Shane Caraveo (:mixedpuppy)]

probably, I'll look into it.

Comment 3

[Intermittent Failures Robot]

26 failures in 3125 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 20
• mozilla-central: 3
• try: 3

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1
• linux1804-64: 17
  • opt: 2
  • debug: 15
• windows10-64-qr: 1
  • debug: 1
• android-em-7-0-x86_64: 1
  • opt: 1
• linux1804-64-asan: 2
  • opt: 2
• linux1804-64-shippable: 3
  • opt: 3
• linux1804-64-devedition: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1701732&startday=2021-03-29&endday=2021-04-04&tree=all

Comment 4

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 33 failures within the last 7 days:

• 1 failure on Windows 7 debug
• 3 failures on Linux 18.04 x64 shippable opt
• 4 failures on Linux 18.04 x64 asan opt
• 25 failures on Linux 18.04 x64 debug/opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=336060163&repo=autoland&lineNumber=3658

[task 2021-04-10T07:04:12.612Z] 07:04:12 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Default engine is Bing -
[task 2021-04-10T07:04:12.613Z] 07:04:12 INFO - Console message: Warning: attempting to write 25384 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2021-04-10T07:04:12.615Z] 07:04:12 INFO - Buffered messages finished
[task 2021-04-10T07:04:12.616Z] 07:04:12 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Test timed out -
[task 2021-04-10T07:04:12.617Z] 07:04:12 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-10T07:04:12.618Z] 07:04:12 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | Extension left running at test shutdown -
[task 2021-04-10T07:04:12.619Z] 07:04:12 INFO - Stack trace:
[task 2021-04-10T07:04:12.620Z] 07:04:12 INFO - chrome://mochikit/content/browser-test.js:test_ok:1334
[task 2021-04-10T07:04:12.621Z] 07:04:12 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:117
[task 2021-04-10T07:04:12.622Z] 07:04:12 INFO - chrome://mochikit/content/browser-test.js:nextTest:571
[task 2021-04-10T07:04:12.623Z] 07:04:12 INFO - Console message: Warning: attempting to write 25320 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2021-04-10T07:04:12.624Z] 07:04:12 INFO - GECKO(1560) | MEMORY STAT | vsize 20976007MB | residentFast 2004MB
[task 2021-04-10T07:04:12.625Z] 07:04:12 INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_settings_overrides_default_search.js | took 90150ms

Comment 5

[Intermittent Failures Robot]

37 failures in 3854 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

This is the #41 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: 3
• autoland: 31
• try: 3

Platform and build breakdown:

• linux1804-64: 30
  • debug: 29
  • opt: 1
• linux1804-64-shippable: 2
  • opt: 2
• linux1804-64-asan: 4
  • opt: 4
• windows7-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1701732&startday=2021-04-05&endday=2021-04-11&tree=all

Comment 6

[Andreea Pavel [:apavel]]

Hi Shane, any updates here?

Comment 7

[Intermittent Failures Robot]

26 failures in 4255 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 22
• try: 3
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-asan: 4
  • opt: 4
• linux1804-64: 22
  • debug: 20
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1701732&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 8

[Luca Greco [:rpl] [:luca] [:lgreco]]

Clearing old needinfo, and removed needswork:owner from the stockwell tracking whiteboard:

• this intermittent doesn't seem to be happening again over the last two months
• looking to the logs from the last failure makes it clear that the last failure did happen at least before the changes applied to that test case from Bug 1641913 did land

I suspect that the changes landed from Bug 1702454 may have also fixed the intermittency (Bug 1702454 landed 2 months ago, which matches the last intermittent failures reported in comment 7).

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.