Open Bug 1875948 Opened 1 year ago Updated 13 days ago

Intermittent toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | single tracking bug

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(thunderbird_esr115 unaffected, firefox-esr115 unaffected, firefox122 unaffected, firefox123 unaffected, firefox124 wontfix)

REOPENED
Tracking Status
thunderbird_esr115 --- unaffected
firefox-esr115 --- unaffected
firefox122 --- unaffected
firefox123 --- unaffected
firefox124 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, intermittent-testcase)

Attachments

(1 obsolete file)

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


[task 2024-01-22T23:11:20.110Z] 23:11:20     INFO -  TEST-START | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html
[task 2024-01-22T23:11:20.110Z] 23:11:20     INFO -  Buffered messages logged at 23:11:12
[task 2024-01-22T23:11:20.110Z] 23:11:20     INFO -  add_setup | Entering
[task 2024-01-22T23:11:20.110Z] 23:11:20     INFO -  add_setup | Leaving
[task 2024-01-22T23:11:20.110Z] 23:11:20     INFO -  add_task | Entering overrideDocumentColors_always
[task 2024-01-22T23:11:20.110Z] 23:11:20     INFO -  Extension loaded
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -  Extension loaded
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -  Buffered messages finished
[task 2024-01-22T23:11:20.111Z] 23:11:20  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | No browser action for 1891791e1388cec25c2149c15cf34fc75365a651@temporary-addon - Should not throw any errors
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -      nextTick/<@SimpleTest/SimpleTest.js:2216:26
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -      async*nextTick@SimpleTest/SimpleTest.js:2233:11
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -      setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:922:41
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -      add_task@SimpleTest/SimpleTest.js:2137:17
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -      add_setup@SimpleTest/SimpleTest.js:2253:10
[task 2024-01-22T23:11:20.111Z] 23:11:20     INFO -      @toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html?currentTestURL=toolkit%2Fcomponents%2Fextensions%2Ftest%2Fmochitest%2Ftest_ext_browserSettings_overrideDocumentColors.html&closeWhenDone=1&showTestReport=false&expected=pass:15:10
[task 2024-01-22T23:11:20.112Z] 23:11:20  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | Extension left running at test shutdown
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:132:18
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1568:13
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1582:3
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      nextTick/<@SimpleTest/SimpleTest.js:2232:22
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      async*nextTick@SimpleTest/SimpleTest.js:2233:11
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:922:41
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      add_task@SimpleTest/SimpleTest.js:2137:17
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      add_setup@SimpleTest/SimpleTest.js:2253:10
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      @toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html?currentTestURL=toolkit%2Fcomponents%2Fextensions%2Ftest%2Fmochitest%2Ftest_ext_browserSettings_overrideDocumentColors.html&closeWhenDone=1&showTestReport=false&expected=pass:15:10
[task 2024-01-22T23:11:20.112Z] 23:11:20  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | Extension left running at test shutdown
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2024-01-22T23:11:20.112Z] 23:11:20     INFO -      ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:132:18
[task 2024-01-22T23:11:20.113Z] 23:11:20     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1568:13
[task 2024-01-22T23:11:20.113Z] 23:11:20     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1578:7
[task 2024-01-22T23:11:20.113Z] 23:11:20     INFO -  TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | took 982ms
[task 2024-01-22T23:11:20.113Z] 23:11:20     INFO -  TEST-START | toolkit/components/extensions/test/mochitest/test_ext_browsingData_indexedDB.html

Tier 1 failure here

Summary: Intermittent [tier 2] toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | single tracking bug → Intermittent toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | single tracking bug

This seems like a pre-existing test-only issue, and not a bug in the functionality added/tested in bug 1873024.
The test_ext_browserSettings_overrideDocumentColors.html test is the first (and only) mochitest that uses AppTestDelegate.clickBrowserAction(window, extension) with the expectation that an extension panel opens.

From logcat (fuller context at the end of the comment), the following three lines (in order) are relevant:

  • WebExtension: handleMessage GeckoView:BrowserAction:Update
  • TestRunnerAPI: Test API: clickBrowserAction
  • No browser action for 1891791e1388cec25c2149c15cf34fc75365a651@temporary-addon

This shows that the clickBrowserAction call happens after the browser action has supposedly been registered. The fact that No browser action for [addon ID] is emitted means that the browser action was somehow not found (in TestRunnerActivity's clickAction method).

We do however expect the BrowserAction to be registered, starting from:

  • ext-browserAction onManifestEntry
  • ext-browserAction onUpdateChange - note tabId is null.
  • "GeckoView:BrowserAction:Update" handled by WebExtensionController actionUpdate with message.session being null (not specific to a tab).
    • There are two ways for this to return early (and thus not register the action):
      • extension being null
      • extension.setActionDelegate not having been called yet.
    • Both of the above are initialized from TestRunnerActivity's refreshExtensionList. The log shows GeckoView:WebExtension:DebuggerListUpdated before GeckoView:BrowserAction:Update, which means that the request that eventually ends up invoking refreshExtensionList is started. From the log is it not possible to tell whether the response to the request (and thus the callback in refreshExtensionList) has been received.

The next step to debug this issue is to determine whether there is a race condition in the test framework that results in the extension and/or action not initializing as expected.

Relevant part of log from logcat from the initial comment (minus non-relevant lines):

01-22 23:11:12.383 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:DebuggerListUpdated
01-22 23:11:12.501 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:OnInstalled
01-22 23:11:12.503 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:OnReady
01-22 23:11:12.548 14171 14187 I GeckoDump: ⰲ겿{"action":"log","time":1705965072547,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Extension loaded","js_source":"TestRunner.js"}ⰲ겿
01-22 23:11:12.582 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:OnInstalling
01-22 23:11:12.606 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:DebuggerListUpdated
01-22 23:11:12.611 14023 14023 D WebExtension: handleMessage GeckoView:BrowserAction:Update
01-22 23:11:12.615 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:OnInstalled
01-22 23:11:12.617 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:OnReady
01-22 23:11:12.642 14023 14023 D WebExtension: handleMessage GeckoView:WebExtension:Message
01-22 23:11:12.642 14023 14023 I TestRunnerAPI: Test API: clickBrowserAction
01-22 23:11:12.651 14023 14023 D WebExtension: handleMessage GeckoView:BrowserAction:Update
01-22 23:11:12.662 14171 14187 I GeckoDump: ⰲ겿{"action":"test_status","time":1705965072662,"thread":null,"pid":null,"source":"mochitest","test":"toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html","subtest":"No browser action for 1891791e1388cec25c2149c15cf34fc75365a651@temporary-addon","status":"FAIL","expected":"PASS","message":"Should not throw any errors","stack":" nextTick/<@SimpleTest/SimpleTest.js:2216:26\n asyncnextTick@SimpleTest/SimpleTest.js:2233:11\n setTimeout handlerSimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:922:41\n add_task@SimpleTest/SimpleTest.js:2137:17\n add_setup@SimpleTest/SimpleTest.js:2253:10\n @toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html?currentTestURL=toolkit%2Fcomponents%2Fextensions%2Ftest%2Fmochitest%2Ftest_ext_browserSettings_overrideDocumentColors.html&closeWhenDone=1&showTestReport=false&expected=pass:15:10\n","js_source":"TestRunner.js"}ⰲ겿

Flags: needinfo?(rob)
Keywords: regression
No longer regressed by: 1873024
See Also: → 1873024
Depends on: 1876317
See Also: → 1876329

Note that on a couple of my try runs this test failed, but it didn't show up in the treeherder results as oranges, but in fact the test crashed. So there may be more failures we haven't noticed.

(In reply to Hiroyuki Ikezoe (:hiro) from comment #4)

Note that on a couple of my try runs this test failed, but it didn't show up in the treeherder results as oranges, but in fact the test crashed. So there may be more failures we haven't noticed.

Filed bug 1877892.

Attachment #9386624 - Attachment is obsolete: true
See Also: → 1882622
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 8 months ago6 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 6 months ago4 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 months ago3 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 months ago1 month ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: