Closed Bug 1484789 Opened 6 years ago Closed 6 years ago

Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Test timed out | Extension left running at test shutdown -

Categories

(WebExtensions :: Untriaged, defect, P5)

Product:
WebExtensions
Component:
Untriaged
Type:
defect

Tracking

(firefox-esr60 unaffected, firefox65 wontfix, firefox66 fixed, firefox67 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla67
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox65 --- wontfix
firefox66 --- fixed
firefox67 --- fixed

People

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

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [TV-bf pass:pass][stockwell fixed])

Attachments

(1 file)

Bug 1484789 - Ensure document flushed before triggering context menu in a browserAction popup test. r?mixedpuppy!
47 bytes, text/x-phabricator-request
Details | Review
Filed by: ncsoregi [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=194889879&repo=autoland https://queue.taskcluster.net/v1/task/T4qUWEIBTa-FPlRX-DO-Fg/runs/0/artifacts/public/logs/live_backing.log [task 2018-08-20T17:04:33.128Z] 17:04:33 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Expect widget not to be overflowed - [task 2018-08-20T17:04:33.130Z] 17:04:33 INFO - Buffered messages logged at 17:03:08 [task 2018-08-20T17:04:33.133Z] 17:04:33 INFO - Console message: [JavaScript Error: "TypeError: doc is null" {file: "resource:///actors/ContextMenuChild.jsm" line: 501}] [task 2018-08-20T17:04:33.135Z] 17:04:33 INFO - Buffered messages finished [task 2018-08-20T17:04:33.136Z] 17:04:33 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Test timed out - [task 2018-08-20T17:04:33.137Z] 17:04:33 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-08-20T17:04:33.137Z] 17:04:33 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Extension left running at test shutdown - [task 2018-08-20T17:04:33.138Z] 17:04:33 INFO - Stack trace: [task 2018-08-20T17:04:33.142Z] 17:04:33 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109 [task 2018-08-20T17:04:33.144Z] 17:04:33 INFO - chrome://mochikit/content/browser-test.js:nextTest:708 [task 2018-08-20T17:04:33.145Z] 17:04:33 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1203 [task 2018-08-20T17:04:33.146Z] 17:04:33 INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1165 [task 2018-08-20T17:04:33.147Z] 17:04:33 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:999 [task 2018-08-20T17:04:33.149Z] 17:04:33 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795 [task 2018-08-20T17:04:33.154Z] 17:04:33 INFO - GECKO(1062) | [Parent 1062, Main Thread] WARNING: NS_ENSURE_TRUE(weakFrame.IsAlive()) failed: file /builds/worker/workspace/build/src/layout/xul/nsXULPopupManager.cpp, line 1164 [task 2018-08-20T17:04:33.156Z] 17:04:33 INFO - GECKO(1062) | ++DOCSHELL 0xe5248400 == 5 [pid = 1120] [id = {4cc3fc52-a08b-40b4-b4e7-d93519b7a3e2}] [task 2018-08-20T17:04:33.157Z] 17:04:33 INFO - GECKO(1062) | ++DOMWINDOW == 9 (0xe9544040) [pid = 1120] [serial = 841] [outer = (nil)] [task 2018-08-20T17:04:33.159Z] 17:04:33 INFO - GECKO(1062) | --DOMWINDOW == 8 (0xe9544040) [pid = 1120] [serial = 841] [outer = (nil)] [url = ] [task 2018-08-20T17:04:33.160Z] 17:04:33 INFO - TEST-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Assertion count 1 is greater than expected range 0-0 assertions. -
> [task 2018-08-20T17:04:33.133Z] 17:04:33 INFO - Console message: [JavaScript Error: "TypeError: doc is null" {file: "resource:///actors/ContextMenuChild.jsm" line: 501}] means that this is similar to bug 1433892 and caused by bug 1478596 .
Depends on: 1478596
There are 25 total failures in the last 7 days. Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=218705306&repo=mozilla-inbound&lineNumber=3215 [task 2018-12-24T20:22:53.411Z] 20:22:53 INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js [task 2018-12-24T20:22:54.265Z] 20:22:54 INFO - GECKO(5707) | JavaScript error: resource:///actors/ContextMenuChild.jsm, line 478: TypeError: doc is null [task 2018-12-24T20:23:38.422Z] 20:23:38 INFO - TEST-INFO | started process screentopng [task 2018-12-24T20:23:38.943Z] 20:23:38 INFO - TEST-INFO | screentopng: exit 0 [task 2018-12-24T20:23:38.944Z] 20:23:38 INFO - Buffered messages logged at 20:22:53 [task 2018-12-24T20:23:38.945Z] 20:23:38 INFO - Entering test bound getTargetElement_in_extension_tab [task 2018-12-24T20:23:38.947Z] 20:23:38 INFO - Extension loaded [task 2018-12-24T20:23:38.948Z] 20:23:38 INFO - Console message: Warning: attempting to write 17019 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 2018-12-24T20:23:38.949Z] 20:23:38 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | should not get element of tab content in background - Expected: null, Actual: null - [task 2018-12-24T20:23:38.953Z] 20:23:38 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | should get element in tab content - Expected: BUTTON, Actual: BUTTON - [task 2018-12-24T20:23:38.954Z] 20:23:38 INFO - Leaving test bound getTargetElement_in_extension_tab [task 2018-12-24T20:23:38.954Z] 20:23:38 INFO - Entering test bound getTargetElement_in_extension_tab_on_click [task 2018-12-24T20:23:38.956Z] 20:23:38 INFO - Extension loaded [task 2018-12-24T20:23:38.957Z] 20:23:38 INFO - Console message: Warning: attempting to write 17099 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 2018-12-24T20:23:38.958Z] 20:23:38 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | should get element in tab content on click - Expected: BUTTON, Actual: BUTTON - [task 2018-12-24T20:23:38.960Z] 20:23:38 INFO - Buffered messages logged at 20:22:54 [task 2018-12-24T20:23:38.961Z] 20:23:38 INFO - Console message: Ignoring response to aborted listener for 1026 [task 2018-12-24T20:23:38.962Z] 20:23:38 INFO - Leaving test bound getTargetElement_in_extension_tab_on_click [task 2018-12-24T20:23:38.963Z] 20:23:38 INFO - Entering test bound getTargetElement_in_browserAction_popup [task 2018-12-24T20:23:38.964Z] 20:23:38 INFO - Extension loaded [task 2018-12-24T20:23:38.965Z] 20:23:38 INFO - Console message: Warning: attempting to write 17179 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 2018-12-24T20:23:38.967Z] 20:23:38 INFO - Console message: Warning: attempting to write 10798 bytes to preference browser.uiCustomization.state. 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 2018-12-24T20:23:38.967Z] 20:23:38 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Expect widget not to be overflowed - [task 2018-12-24T20:23:38.971Z] 20:23:38 INFO - Console message: [JavaScript Error: "TypeError: doc is null" {file: "resource:///actors/ContextMenuChild.jsm" line: 478}] [task 2018-12-24T20:23:38.972Z] 20:23:38 INFO - Buffered messages finished [task 2018-12-24T20:23:38.973Z] 20:23:38 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Test timed out - [task 2018-12-24T20:23:38.974Z] 20:23:38 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-12-24T20:23:38.978Z] 20:23:38 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Extension left running at test shutdown - [task 2018-12-24T20:23:38.981Z] 20:23:38 INFO - Stack trace: [task 2018-12-24T20:23:38.983Z] 20:23:38 INFO - chrome://mochikit/content/browser-test.js:test_ok:1305 [task 2018-12-24T20:23:38.984Z] 20:23:38 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109 [task 2018-12-24T20:23:38.985Z] 20:23:38 INFO - chrome://mochikit/content/browser-test.js:nextTest:705 [task 2018-12-24T20:23:38.985Z] 20:23:38 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1203 [task 2018-12-24T20:23:38.987Z] 20:23:38 INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1165 [task 2018-12-24T20:23:38.988Z] 20:23:38 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995 [task 2018-12-24T20:23:38.988Z] 20:23:38 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:focusedOrLoaded/<:803 [task 2018-12-24T20:23:38.989Z] 20:23:38 INFO - GECKO(5707) | MEMORY STAT | vsize 2239MB | residentFast 384MB | heapAllocated 112MB [task 2018-12-24T20:23:38.990Z] 20:23:38 INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | took 45102ms David can you take a look or assign someone for this?
Flags: needinfo?(ddurst)
Whiteboard: [TV-bf pass:pass] → [TV-bf pass:pass][stockwell needswork:owner]

David any updates here?

There are 24 total failures in the last 7 days on linux64, linux32 opt, pgo

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

[task 2019-02-09T11:28:16.169Z] 11:28:16 INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js
[task 2019-02-09T11:28:16.856Z] 11:28:16 INFO - GECKO(3865) | JavaScript error: resource:///actors/ContextMenuChild.jsm, line 478: TypeError: doc is null
[task 2019-02-09T11:29:01.182Z] 11:29:01 INFO - TEST-INFO | started process screentopng
[task 2019-02-09T11:29:01.655Z] 11:29:01 INFO - TEST-INFO | screentopng: exit 0
[task 2019-02-09T11:29:01.655Z] 11:29:01 INFO - Buffered messages logged at 11:28:16
[task 2019-02-09T11:29:01.655Z] 11:29:01 INFO - Entering test bound getTargetElement_in_extension_tab
[task 2019-02-09T11:29:01.655Z] 11:29:01 INFO - Extension loaded
[task 2019-02-09T11:29:01.655Z] 11:29:01 INFO - Console message: Warning: attempting to write 16714 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 2019-02-09T11:29:01.655Z] 11:29:01 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | should not get element of tab content in background - Expected: null, Actual: null -
[task 2019-02-09T11:29:01.655Z] 11:29:01 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | should get element in tab content - Expected: BUTTON, Actual: BUTTON -
[task 2019-02-09T11:29:01.656Z] 11:29:01 INFO - Leaving test bound getTargetElement_in_extension_tab
[task 2019-02-09T11:29:01.657Z] 11:29:01 INFO - Entering test bound getTargetElement_in_extension_tab_on_click
[task 2019-02-09T11:29:01.657Z] 11:29:01 INFO - Extension loaded
[task 2019-02-09T11:29:01.657Z] 11:29:01 INFO - Console message: Warning: attempting to write 16794 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 2019-02-09T11:29:01.659Z] 11:29:01 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | should get element in tab content on click - Expected: BUTTON, Actual: BUTTON -
[task 2019-02-09T11:29:01.660Z] 11:29:01 INFO - Console message: Ignoring response to aborted listener for 998
[task 2019-02-09T11:29:01.662Z] 11:29:01 INFO - Leaving test bound getTargetElement_in_extension_tab_on_click
[task 2019-02-09T11:29:01.664Z] 11:29:01 INFO - Entering test bound getTargetElement_in_browserAction_popup
[task 2019-02-09T11:29:01.665Z] 11:29:01 INFO - Extension loaded
[task 2019-02-09T11:29:01.667Z] 11:29:01 INFO - Console message: Warning: attempting to write 16874 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 2019-02-09T11:29:01.668Z] 11:29:01 INFO - Console message: Warning: attempting to write 9342 bytes to preference browser.uiCustomization.state. 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 2019-02-09T11:29:01.669Z] 11:29:01 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Expect widget not to be overflowed -
[task 2019-02-09T11:29:01.670Z] 11:29:01 INFO - Console message: [JavaScript Error: "TypeError: doc is null" {file: "resource:///actors/ContextMenuChild.jsm" line: 478}]
[task 2019-02-09T11:29:01.671Z] 11:29:01 INFO - Buffered messages finished
[task 2019-02-09T11:29:01.672Z] 11:29:01 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Test timed out -
[task 2019-02-09T11:29:01.673Z] 11:29:01 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-02-09T11:29:01.674Z] 11:29:01 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | Extension left running at test shutdown -
[task 2019-02-09T11:29:01.675Z] 11:29:01 INFO - Stack trace:
[task 2019-02-09T11:29:01.676Z] 11:29:01 INFO - chrome://mochikit/content/browser-test.js:test_ok:1304
[task 2019-02-09T11:29:01.677Z] 11:29:01 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2019-02-09T11:29:01.678Z] 11:29:01 INFO - chrome://mochikit/content/browser-test.js:nextTest:705
[task 2019-02-09T11:29:01.678Z] 11:29:01 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1202
[task 2019-02-09T11:29:01.679Z] 11:29:01 INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1164
[task 2019-02-09T11:29:01.680Z] 11:29:01 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2019-02-09T11:29:01.680Z] 11:29:01 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-02-09T11:29:01.682Z] 11:29:01 INFO - GECKO(3865) | JavaScript error: resource://gre/modules/WebProgressChild.jsm, line 58: NS_ERROR_UNEXPECTED:
[task 2019-02-09T11:29:01.683Z] 11:29:01 INFO - Console message: [JavaScript Error: "NS_ERROR_UNEXPECTED: " {file: "resource://gre/modules/WebProgressChild.jsm" line: 58}]
[task 2019-02-09T11:29:01.684Z] 11:29:01 INFO - GECKO(3865) | MEMORY STAT | vsize 2341MB | residentFast 425MB | heapAllocated 147MB
[task 2019-02-09T11:29:01.686Z] 11:29:01 INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_menus_targetElement_extension.js | took 45085ms

Flags: needinfo?(ddurst)
Flags: needinfo?(ddurst)
Whiteboard: [TV-bf pass:pass][stockwell unknown] → [TV-bf pass:pass][stockwell needswork:owner]

The intermittent failures from this test are always happening from the test task that is opening a context menu in a browserAction popup.

I have experienced a similar issue in Bug 1518883, which was intermittently failing for the same underlying reason (the one that triggers the [JavaScript Error: "TypeError: doc is null" {file: "resource:///actors/ContextMenuChild.jsm" line: 478}] error message logged in the console right before the test gets stuck and then time out).

For Bug 1518883 I investigated it quite a bit before looking for a workaround, and as I described in Bug 1519808, the issue seems to be happening when a test is using DOMWindowUtils.sendMouseEvent (usually indirectly, by calling BrowserTestUtils.synthesizeMouse* helpers) to trigger a mouse event on a newly created remote browser element.

Locally I've also quickly verified that the workaround used for Bug 1518883 is also working on this intermittent, in short replacing

await BrowserTestUtils.synthesizeMouseAtCenter(selector, {type: "contextmenu"}, browser);

with something like:

await ContentTask.spawn(browser, null, () => {
  let el = content.document.querySelector(selector);
  el.dispatchEvent(new content.MouseEvent("contextmenu", {view: el.ownerGlobal, ...}));
});

triggers the context menu on the expected DOM element consistently, whereas the original BrowserTestUtils.synthesizeMouseAtCenter intermittently triggers it on the entire HTML document.

Bug 1519808 seems to be the actual issue behind a bunch of our intermittents, and so it may be more reasonable to have it investigated so that we may fix it instead of applying the above workaround.

Flags: needinfo?(ddurst)
See Also: → 1519808
Pushed by luca.greco@alcacoop.it: https://hg.mozilla.org/integration/autoland/rev/22ea69aeb24d Ensure document flushed before triggering context menu in a browserAction popup test. r=mixedpuppy

https://hg.mozilla.org/mozilla-central/rev/22ea69aeb24d

Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox67: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
Assignee: nobody → lgreco
Whiteboard: [TV-bf pass:pass][stockwell unknown] → [TV-bf pass:pass][stockwell fixed]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: