1763042 - Intermittent browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | Test timed out | no tasks awaiting on messages - Got "[\"done\"]", expected "[]"

Status: RESOLVED DUPLICATE of bug 1763043

(WebExtensions :: Untriaged, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-04-05T01:50:03.056Z] 01:50:03     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | no error creating menu - "undefined" == "undefined" - 
[task 2022-04-05T01:50:03.057Z] 01:50:03     INFO - Buffered messages finished
[task 2022-04-05T01:50:03.057Z] 01:50:03     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | Test timed out - 
[task 2022-04-05T01:50:03.058Z] 01:50:03     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | no tasks awaiting on messages - Got "[\"done\"]", expected "[]"
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - Stack trace:
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:test_is:1422
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:52
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:nextTest:561
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1282
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1222
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:978
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041
[task 2022-04-05T01:50:03.059Z] 01:50:03     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-04-05T01:50:03.060Z] 01:50:03     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | Extension left running at test shutdown - 
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - Stack trace:
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:test_ok:1394
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:133
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:nextTest:561
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1282
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1222
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:978
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041
[task 2022-04-05T01:50:03.061Z] 01:50:03     INFO - Console message: [JavaScript Warning: "browser.ui.customized_widgets - The key length must be limited to 72 characters."]
[task 2022-04-05T01:50:03.062Z] 01:50:03     INFO - GECKO(1544) | monitorConsole | extra message | {"message":"[JavaScript Warning: \"browser.ui.customized_widgets - The key length must be limited to 72 characters.\"]","errorMessage":"browser.ui.customized_widgets - The key length must be limited to 72 characters.","cssSelectors":"","sourceName":"","sourceLine":"","lineNumber":0,"columnNumber":0,"category":"chrome javascript","windowID":0,"isScriptError":true,"isConsoleEvent":false,"isWarning":true,"innerWindowID":0}
[task 2022-04-05T01:50:03.063Z] 01:50:03     INFO - Console message: Warning: attempting to write 17017 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 2022-04-05T01:50:03.064Z] 01:50:03     INFO - GECKO(1544) | monitorConsole | extra message | {"message":"Warning: attempting to write 17017 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.","errorMessage":null,"cssSelectors":null,"sourceName":null,"sourceLine":null,"lineNumber":null,"columnNumber":null,"category":null,"windowID":null,"isScriptError":false,"isConsoleEvent":false,"isWarning":false}
[task 2022-04-05T01:50:03.064Z] 01:50:03     INFO - GECKO(1544) | MEMORY STAT | vsize 8619MB | residentFast 737MB | heapAllocated 219MB
[task 2022-04-05T01:50:03.065Z] 01:50:03     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | took 90196ms

Comment 1

[Intermittent Failures Robot]

31 failures in 648 pushes (0.048 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 30
• mozilla-central: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1
• linux1804-64-tsan-qr: 9
  • opt: 9
• linux1804-64-qr: 21
  • debug: 21

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

Comment 2

[Intermittent Failures Robot]

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

This is the #8 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:

• autoland: 51
• mozilla-central: 4

Platform and build breakdown:

• linux1804-64-qr: 32
  • debug: 32
• macosx1015-64-qr: 3
  • debug: 3
• linux1804-64-tsan-qr: 20
  • opt: 20

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1763042&startday=2022-04-04&endday=2022-04-10&tree=all

Comment 3

[Iulian Moraru]

Update:
There have been 42 failures within the last 7 days:
• 23 failures on Linux 18.04 x64 WebRender debug
• 19 failures on Linux 18.04 x64 WebRender tsan opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=374715705&repo=mozilla-central&lineNumber=13564

[task 2022-04-16T10:29:51.958Z] 10:29:51     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | expected msg - Expected: add-again, Actual: add-again - 
[task 2022-04-16T10:29:51.962Z] 10:29:51     INFO - Console message: [JavaScript Error: "WebExtension context not found!" {file: "resource://gre/modules/ExtensionParent.jsm" line: 1119}]
[task 2022-04-16T10:29:51.963Z] 10:29:51     INFO - getContextById@resource://gre/modules/ExtensionParent.jsm:1119:13
[task 2022-04-16T10:29:51.964Z] 10:29:51     INFO - recvAPICall@resource://gre/modules/ExtensionParent.jsm:964:24
[task 2022-04-16T10:29:51.965Z] 10:29:51     INFO - _recv@resource://gre/modules/ConduitsChild.jsm:82:20
[task 2022-04-16T10:29:51.965Z] 10:29:51     INFO - receiveMessage@resource://gre/modules/ConduitsParent.jsm:450:20
[task 2022-04-16T10:29:51.966Z] 10:29:51     INFO - JSActor query*_send@resource://gre/modules/ConduitsChild.jsm:67:11
[task 2022-04-16T10:29:51.967Z] 10:29:51     INFO - _send@resource://gre/modules/ConduitsChild.jsm:115:18
[task 2022-04-16T10:29:51.968Z] 10:29:51     INFO - callParentAsyncFunction@resource://gre/modules/ExtensionChild.jsm:884:18
[task 2022-04-16T10:29:51.969Z] 10:29:51     INFO - create@chrome://browser/content/child/ext-menus.js:146:14
[task 2022-04-16T10:29:51.970Z] 10:29:51     INFO - callFunction@resource://gre/modules/ExtensionCommon.jsm:1109:37
[task 2022-04-16T10:29:51.970Z] 10:29:51     INFO - callFunction/<@resource://gre/modules/ExtensionChild.jsm:731:40
[task 2022-04-16T10:29:51.971Z] 10:29:51     INFO - callAndLog@resource://gre/modules/ExtensionChild.jsm:711:14
[task 2022-04-16T10:29:51.972Z] 10:29:51     INFO - callFunction@resource://gre/modules/ExtensionChild.jsm:731:17
[task 2022-04-16T10:29:51.972Z] 10:29:51     INFO - stub@resource://gre/modules/Schemas.jsm:2861:30
[task 2022-04-16T10:29:51.973Z] 10:29:51     INFO - @moz-extension://b249821b-1515-4eab-8da5-d8a1f2f0cb7b/%7B10b7893c-b37c-4611-9475-e117ea29e624%7D.js:14:21
[task 2022-04-16T10:29:51.973Z] 10:29:51     INFO - listenerWrapper@chrome://extensions/content/child/ext-test.js:131:22
[task 2022-04-16T10:29:51.974Z] 10:29:51     INFO - applySafeWithoutClone@resource://gre/modules/ExtensionCommon.jsm:692:24
[task 2022-04-16T10:29:51.975Z] 10:29:51     INFO - applySafe@resource://gre/modules/ExtensionCommon.jsm:675:19
[task 2022-04-16T10:29:51.975Z] 10:29:51     INFO - addListener/async/<@resource://gre/modules/ExtensionCommon.jsm:2577:39
[task 2022-04-16T10:29:51.976Z] 10:29:51     INFO - promise callback*async@resource://gre/modules/ExtensionCommon.jsm:2574:34
[task 2022-04-16T10:29:51.976Z] 10:29:51     INFO - handler@chrome://extensions/content/child/ext-test.js:287:20
[task 2022-04-16T10:29:51.977Z] 10:29:51     INFO - emit@resource://gre/modules/ExtensionCommon.jsm:322:32
[task 2022-04-16T10:29:51.978Z] 10:29:51     INFO - receiveMessage@resource://gre/modules/ExtensionChild.jsm:562:13
[task 2022-04-16T10:29:51.978Z] 10:29:51     INFO - MessageListener.receiveMessage*BrowserExtensionContent@resource://gre/modules/ExtensionChild.jsm:400:19
[task 2022-04-16T10:29:51.979Z] 10:29:51     INFO - extensions<@resource://gre/modules/ExtensionProcessScript.jsm:63:10
[task 2022-04-16T10:29:51.980Z] 10:29:51     INFO - get@resource://gre/modules/ExtensionUtils.jsm:101:20
[task 2022-04-16T10:29:51.981Z] 10:29:51     INFO - initExtensionDocument@resource://gre/modules/ExtensionProcessScript.jsm:340:32
[task 2022-04-16T10:29:51.981Z] 10:29:51     INFO - 
[task 2022-04-16T10:29:51.983Z] 10:29:51     INFO - Buffered messages logged at 10:27:51
[task 2022-04-16T10:29:51.986Z] 10:29:51     INFO - Console message: [JavaScript Error: "1650104871598	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2022-04-16T10:29:51.989Z] 10:29:51     INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2022-04-16T10:29:51.990Z] 10:29:51     INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2022-04-16T10:29:51.990Z] 10:29:51     INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2022-04-16T10:29:51.991Z] 10:29:51     INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4070:25
[task 2022-04-16T10:29:51.992Z] 10:29:51     INFO - promise callback*updateSystemAddons@resource://gre/modules/addons/XPIInstall.jsm:4070:7
[task 2022-04-16T10:29:51.993Z] 10:29:51     INFO - async*XPIProvider[meth]@resource://gre/modules/addons/XPIProvider.jsm:3273:28
[task 2022-04-16T10:29:51.993Z] 10:29:51     INFO - backgroundUpdateCheck/buPromise<@resource://gre/modules/AddonManager.jsm:1303:13
[task 2022-04-16T10:29:51.994Z] 10:29:51     INFO - backgroundUpdateCheck@resource://gre/modules/AddonManager.jsm:1311:7
[task 2022-04-16T10:29:51.995Z] 10:29:51     INFO - backgroundUpdateTimerHandler@resource://gre/modules/AddonManager.jsm:3526:26
[task 2022-04-16T10:29:51.995Z] 10:29:51     INFO - notify@resource://gre/modules/addonManager.js:174:25
[task 2022-04-16T10:29:51.996Z] 10:29:51     INFO - TM_notify/<@resource://gre/modules/UpdateTimerManager.jsm:223:50
[task 2022-04-16T10:29:51.997Z] 10:29:51     INFO - TM_notify@resource://gre/modules/UpdateTimerManager.jsm:294:7
[task 2022-04-16T10:29:51.998Z] 10:29:51     INFO - 
[task 2022-04-16T10:29:51.999Z] 10:29:51     INFO - Buffered messages finished
[task 2022-04-16T10:29:52.000Z] 10:29:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | Test timed out - 
[task 2022-04-16T10:29:52.001Z] 10:29:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-04-16T10:29:52.004Z] 10:29:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | no tasks awaiting on messages - Got "[\"done\"]", expected "[]"
[task 2022-04-16T10:29:52.004Z] 10:29:52     INFO - Stack trace:
[task 2022-04-16T10:29:52.005Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:test_is:1422
[task 2022-04-16T10:29:52.006Z] 10:29:52     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:52
[task 2022-04-16T10:29:52.007Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:nextTest:561
[task 2022-04-16T10:29:52.007Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1282
[task 2022-04-16T10:29:52.008Z] 10:29:52     INFO - setTimeout handler*chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest_setTimeoutShim:907
[task 2022-04-16T10:29:52.009Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1263
[task 2022-04-16T10:29:52.010Z] 10:29:52     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1222
[task 2022-04-16T10:29:52.010Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:978
[task 2022-04-16T10:29:52.011Z] 10:29:52     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041
[task 2022-04-16T10:29:52.012Z] 10:29:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-04-16T10:29:52.014Z] 10:29:52     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | Extension left running at test shutdown - 
[task 2022-04-16T10:29:52.015Z] 10:29:52     INFO - Stack trace:
[task 2022-04-16T10:29:52.016Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:test_ok:1394
[task 2022-04-16T10:29:52.017Z] 10:29:52     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:133
[task 2022-04-16T10:29:52.017Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:nextTest:561
[task 2022-04-16T10:29:52.018Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1282
[task 2022-04-16T10:29:52.019Z] 10:29:52     INFO - setTimeout handler*chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest_setTimeoutShim:907
[task 2022-04-16T10:29:52.020Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1263
[task 2022-04-16T10:29:52.020Z] 10:29:52     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1222
[task 2022-04-16T10:29:52.021Z] 10:29:52     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:978
[task 2022-04-16T10:29:52.022Z] 10:29:52     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041
[task 2022-04-16T10:29:52.023Z] 10:29:52     INFO - Console message: [JavaScript Warning: "browser.ui.customized_widgets - The key length must be limited to 72 characters."]
[task 2022-04-16T10:29:52.025Z] 10:29:52     INFO - GECKO(1575) | monitorConsole | extra message | {"message":"[JavaScript Warning: \"browser.ui.customized_widgets - The key length must be limited to 72 characters.\"]","errorMessage":"browser.ui.customized_widgets - The key length must be limited to 72 characters.","cssSelectors":"","sourceName":"","sourceLine":"","lineNumber":0,"columnNumber":0,"category":"chrome javascript","windowID":0,"isScriptError":true,"isConsoleEvent":false,"isWarning":true,"innerWindowID":0}
[task 2022-04-16T10:29:52.026Z] 10:29:52     INFO - Console message: Warning: attempting to write 16377 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 2022-04-16T10:29:52.028Z] 10:29:52     INFO - GECKO(1575) | monitorConsole | extra message | {"message":"Warning: attempting to write 16377 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.","errorMessage":null,"cssSelectors":null,"sourceName":null,"sourceLine":null,"lineNumber":null,"columnNumber":null,"category":null,"windowID":null,"isScriptError":false,"isConsoleEvent":false,"isWarning":false}
[task 2022-04-16T10:29:52.030Z] 10:29:52     INFO - GECKO(1575) | MEMORY STAT | vsize 3873MB | residentFast 754MB | heapAllocated 427MB
[task 2022-04-16T10:29:52.031Z] 10:29:52     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_menus_eventpage.js | took 180223ms
[task 2022-04-16T10:29:52.032Z] 10:29:52     INFO - GECKO(1575) | [Child 1699: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f20d0e05800 == 1 [pid = 1699] [id = 62]
[task 2022-04-16T10:29:52.035Z] 10:29:52     INFO - GECKO(1575) | [Child 1699: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f20e6c959f0) [pid = 1699] [serial = 133] [outer = 0]
[task 2022-04-16T10:29:52.036Z] 10:29:52     INFO - GECKO(1575) | [Child 1699: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f20d0e05c00) [pid = 1699] [serial = 134] [outer = 7f20e6c959f0]
[task 2022-04-16T10:29:52.037Z] 10:29:52     INFO - checking window state
[task 2022-04-16T10:29:52.061Z] 10:29:52     INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_menus_events.js

Comment 4

[Intermittent Failures Robot]

41 failures in 2948 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #15 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:

• autoland: 34
• mozilla-central: 7

Platform and build breakdown:

• linux1804-64-tsan-qr: 19
  • opt: 19
• linux1804-64-qr: 22
  • debug: 22

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

Comment 5

[Shane Caraveo (:mixedpuppy)]

Also likely fixed by reworking this test file in bug 1763043