Closed Bug 1817632 Opened 2 years ago Closed 1 month ago

Intermittent browser/components/extensions/test/browser/browser_ext_omnibox.js | single tracking bug

Categories

(WebExtensions :: Untriaged, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [stockwell unknown])

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=406162090&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GNOUes1OQ7-J-01jYhWrtA/runs/0/artifacts/public/logs/live_backing.log


[task 2023-02-19T11:23:35.357Z] 11:23:35     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_omnibox.js | Expected "on-input-changed-fired to have fired." - 
[task 2023-02-19T11:23:35.358Z] 11:23:35     INFO - Waiting for event: on-delete-suggestion-fired (Caller lines: 103, 260, 366)
[task 2023-02-19T11:23:35.358Z] 11:23:35     INFO - Buffered messages logged at 11:22:41
[task 2023-02-19T11:23:35.360Z] 11:23:35     INFO - Console message: [JavaScript Error: "1676805761660	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-19T11:23:35.360Z] 11:23:35     INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4104:25
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - promise callback*updateSystemAddons@resource://gre/modules/addons/XPIInstall.jsm:4104:7
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - async*XPIProvider[meth]@resource://gre/modules/addons/XPIProvider.jsm:3291:33
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - backgroundUpdateCheck/buPromise<@resource://gre/modules/AddonManager.jsm:1320:13
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - backgroundUpdateCheck@resource://gre/modules/AddonManager.jsm:1328:7
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - backgroundUpdateTimerHandler@resource://gre/modules/AddonManager.jsm:3749:26
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - notify@resource://gre/modules/addonManager.js:171:25
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - TM_notify/<@resource://gre/modules/UpdateTimerManager.jsm:224:50
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - TM_notify@resource://gre/modules/UpdateTimerManager.jsm:295:7
[task 2023-02-19T11:23:35.361Z] 11:23:35     INFO - 
[task 2023-02-19T11:23:35.362Z] 11:23:35     INFO - Buffered messages finished
[task 2023-02-19T11:23:35.362Z] 11:23:35     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_omnibox.js | Test timed out - 
[task 2023-02-19T11:23:35.363Z] 11:23:35     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_omnibox.js | message queue is empty - "Got \"[\\\"on-input-started-fired\\\"]\", expected \"[]\""
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - Stack trace:
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:test_is:1493
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:47
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:nextTest:611
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1344
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1284
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1026
[task 2023-02-19T11:23:35.365Z] 11:23:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1036
[task 2023-02-19T11:23:35.366Z] 11:23:35     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_omnibox.js | no tasks awaiting on messages - "Got \"[\\\"on-delete-suggestion-fired\\\"]\", expected \"[]\""
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - Stack trace:
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:test_is:1493
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:51
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:nextTest:611
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1344
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1284
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1026
[task 2023-02-19T11:23:35.368Z] 11:23:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1036
[task 2023-02-19T11:23:35.369Z] 11:23:35     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_omnibox.js | Extension left running at test shutdown - 
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - Stack trace:
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:test_ok:1465
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:132
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:nextTest:611
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1344
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1284
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1026
[task 2023-02-19T11:23:35.370Z] 11:23:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1036
[task 2023-02-19T11:23:35.371Z] 11:23:35     INFO - GECKO(4048) | [Child 5728, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-02-19T11:23:35.372Z] 11:23:35     INFO - Console message: [JavaScript Error: "sendRemoveListener on closed conduit {d9b12aa1-ba70-4cd8-b468-494dd57872b7}.274877910284" {file: "resource://gre/modules/ConduitsChild.jsm" line: 115}]
[task 2023-02-19T11:23:35.372Z] 11:23:35     INFO - _send@resource://gre/modules/ConduitsChild.jsm:115:13
[task 2023-02-19T11:23:35.372Z] 11:23:35     INFO - removeListener@resource://gre/modules/ExtensionChild.jsm:671:34
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - removeListener@resource://gre/modules/ExtensionChild.jsm:931:40
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - getAPI/register/<.omnibox.onInputChanged@chrome://browser/content/child/ext-omnibox.js:31:18
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - removeListener@resource://gre/modules/ExtensionCommon.jsm:2725:7
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - revoke@resource://gre/modules/ExtensionCommon.jsm:2747:12
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - close@resource://gre/modules/ExtensionCommon.jsm:2752:10
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - unload@resource://gre/modules/ExtensionCommon.jsm:983:11
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - unload@resource://gre/modules/ExtensionPageChild.jsm:301:11
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - unload@resource://gre/modules/ExtensionPageChild.jsm:338:11
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - destroyExtensionContext@resource://gre/modules/ExtensionPageChild.jsm:502:15
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - observe@resource://gre/modules/ExtensionPageChild.jsm:407:12
[task 2023-02-19T11:23:35.373Z] 11:23:35     INFO - 
[task 2023-02-19T11:23:35.374Z] 11:23:35     INFO - GECKO(4048) | MEMORY STAT | vsize 2104676MB | vsizeMaxContiguous 67757362MB | residentFast 508MB | heapAllocated 193MB
[task 2023-02-19T11:23:35.374Z] 11:23:35     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_omnibox.js | took 90089ms
[task 2023-02-19T11:23:35.375Z] 11:23:35     INFO - GECKO(4048) | [Child 5664: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 1d1d5481000 == 1 [pid = 5664] [id = 76]
[task 2023-02-19T11:23:35.376Z] 11:23:35     INFO - GECKO(4048) | [Child 5664: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (1d1d047fc30) [pid = 5664] [serial = 158] [outer = 0]
[task 2023-02-19T11:23:35.376Z] 11:23:35     INFO - GECKO(4048) | [Child 5664: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (1d1d5481c00) [pid = 5664] [serial = 159] [outer = 1d1d047fc30]
[task 2023-02-19T11:23:35.377Z] 11:23:35     INFO - checking window state
[task 2023-02-19T11:23:35.398Z] 11:23:35     INFO - GECKO(4048) | [Child 5728: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 1d888f88c00 == 5 [pid = 5728] [id = 518] [url = moz-extension://a3c1436e-1a8c-4744-9de1-74f389291f4c/_generated_background_page.html]
[task 2023-02-19T11:23:35.408Z] 11:23:35     INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_openPanel.js

Thanks to the logging added in bug 1784662, it is easier to trace what's happening.

In the log above, the last status before the timeout is:

Waiting for event: on-delete-suggestion-fired (Caller lines: 103, 260, 366)

That is not the only instance, I also see it in other failures that had been associated with bug 1784662, e.g. 2 days ago at https://treeherder.mozilla.org/logviewer?job_id=406009958&repo=mozilla-central&lineNumber=31737

If the frequency of failures persist, we may have to investigate whether the test added in bug 1478095 could potentially be triggering this specific issue, since the test is stuck at testSuggestionDeletion (line 366).

See Also: → 1478095

Update:

There have been 36 failures within the last 7 days:

  • 19 failures on Linux 18.04 x64 WebRender debug/opt
  • 1 failure on Linux 18.04 x64 WebRender Shippable opt
  • 1 failure on Linux 18.04 x64 WebRender tsan opt
  • 1 failure on OS X 10.15 WebRender debug
  • 3 failures on Windows 10 x86 2004 WebRender debug
  • 9 failures on Windows 10 x64 2004 WebRender debug

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

Whiteboard: [stockwell needswork:owner]

There have been 47 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • linux1804-64-qr
  • linux1804-64-shippable-qr
  • linux1804-64-tsan-qr
  • macosx1015-64-qr
  • windows10-32-2004-qr
  • windows10-64-2004-asan-qr
  • windows10-64-2004-qr
  • windows11-32-2009-qr
  • windows11-64-2009-ccov-qr
  • windows11-64-2009-qr
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago4 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 months ago1 month ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.