1856265 - Intermittent toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | single tracking bug

Status: RESOLVED INCOMPLETE

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-10-02T00:38:47.042Z] 00:38:47     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript.html | took 16836ms
[task 2023-10-02T00:38:47.122Z] 00:38:47     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html
[task 2023-10-02T00:38:51.275Z] 00:38:51     INFO - GECKO(3455) | [Parent 3455, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3108
[task 2023-10-02T00:38:52.463Z] 00:38:52     INFO - GECKO(3455) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/bw/xjldm9qd6qd4ds3b975m5gmm000014/T/tmphpjkkrsi.mozrunner/runtests_leaks_tab_pid3863.log
[task 2023-10-02T00:38:52.841Z] 00:38:52     INFO - GECKO(3455) | Console message: Warning: attempting to write 12497 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.
[task 2023-10-02T00:38:52.853Z] 00:38:52     INFO - GECKO(3455) | JavaScript error: chrome://browser/content/places/browserPlacesViews.js, line 116: Error: No DOM node set for aPlacesNode.
[task 2023-10-02T00:38:52.854Z] 00:38:52     INFO - GECKO(3455) | node.type: 0. node.parent: [xpconnect wrapped nsINavHistoryResultNode @ 0x130a831c0 (native @ 0x139df4100)]
[task 2023-10-02T00:38:52.855Z] 00:38:52     INFO - GECKO(3455) | Console message: [JavaScript Error: "Error: No DOM node set for aPlacesNode.
[task 2023-10-02T00:38:52.856Z] 00:38:52     INFO - GECKO(3455) | node.type: 0. node.parent: [xpconnect wrapped nsINavHistoryResultNode @ 0x130a831c0 (native @ 0x139df4100)]" {file: "chrome://browser/content/places/browserPlacesViews.js" line: 116}]
[task 2023-10-02T00:38:52.856Z] 00:38:52     INFO - GECKO(3455) | _getDOMNodeForPlacesNode@chrome://browser/content/places/browserPlacesViews.js:116:13
[task 2023-10-02T00:38:52.856Z] 00:38:52     INFO - GECKO(3455) | nodeMoved@chrome://browser/content/places/browserPlacesViews.js:583:20
[task 2023-10-02T00:38:53.346Z] 00:38:53     INFO - GECKO(3455) | [Child 3456, Main Thread] WARNING: Fallback to FallbackRenderer: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2656
[task 2023-10-02T00:38:53.357Z] 00:38:53     INFO - GECKO(3455) | Console message: [JavaScript Warning: "browser.ui.customized_widgets - The key length must be limited to 72 characters."]
[task 2023-10-02T00:38:53.958Z] 00:38:53     INFO - GECKO(3455) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/bw/xjldm9qd6qd4ds3b975m5gmm000014/T/tmphpjkkrsi.mozrunner/runtests_leaks_tab_pid3864.log
[task 2023-10-02T00:39:23.513Z] 00:39:23     INFO - GECKO(3455) | [Child 3456, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-10-02T00:44:07.175Z] 00:44:07     INFO - TEST-INFO | started process screencapture
[task 2023-10-02T00:44:07.297Z] 00:44:07     INFO - TEST-INFO | screencapture: exit 0
[task 2023-10-02T00:44:07.297Z] 00:44:07     INFO - Buffered messages logged at 00:38:51
[task 2023-10-02T00:44:07.297Z] 00:44:07     INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2023-10-02T00:44:07.298Z] 00:44:07     INFO - Buffered messages logged at 00:38:52
[task 2023-10-02T00:44:07.298Z] 00:44:07     INFO - add_task | Entering setup
[task 2023-10-02T00:44:07.298Z] 00:44:07     INFO - add_task | Leaving setup
[task 2023-10-02T00:44:07.299Z] 00:44:07     INFO - add_task | Entering test_executeScript_activeTab_permission
[task 2023-10-02T00:44:07.299Z] 00:44:07     INFO - Extension loaded
[task 2023-10-02T00:44:07.299Z] 00:44:07     INFO - Buffered messages finished
[task 2023-10-02T00:44:07.300Z] 00:44:07     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | Test timed out. - 
[task 2023-10-02T00:44:08.197Z] 00:44:08     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | Extension left running at test shutdown 
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO -     ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:132:18
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1568:13
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1582:3
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO -     @SimpleTest/SimpleTest.js:2265:16
[task 2023-10-02T00:44:08.198Z] 00:44:08     INFO -     async*@SimpleTest/SimpleTest.js:2262:17
[task 2023-10-02T00:44:09.369Z] 00:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-10-02T00:44:09.369Z] 00:44:09     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | Test left extra windows or tabs: {"extraWindows":{},"extraTabs":{"0":"https://test1.example.com/tests/toolkit/components/extensions/test/mochitest/file_sample.html"}}
[task 2023-10-02T00:44:09.369Z] 00:44:09     INFO -  
[task 2023-10-02T00:44:09.369Z] 00:44:09     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2023-10-02T00:44:09.369Z] 00:44:09     INFO -     @toolkit/components/extensions/test/mochitest/head.js:26:9
[task 2023-10-02T00:44:09.370Z] 00:44:09     INFO -     async*executeCleanupFunction@SimpleTest/SimpleTest.js:1568:13
[task 2023-10-02T00:44:09.370Z] 00:44:09     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1578:7
[task 2023-10-02T00:44:09.381Z] 00:44:09     INFO - GECKO(3455) | MEMORY STAT | vsize 6706MB | residentFast 120MB | heapAllocated 8MB
[task 2023-10-02T00:44:13.708Z] 00:44:13     INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2023-10-02T00:44:13.722Z] 00:44:13     INFO - GECKO(3455) | [Parent 3455, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3984
[task 2023-10-02T00:44:13.723Z] 00:44:13     INFO - GECKO(3455) | [Parent 3455, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3984
[task 2023-10-02T00:44:13.724Z] 00:44:13     INFO - GECKO(3455) | JavaScript error: resource://testing-common/WrapPrivileged.sys.mjs, line 134: SecurityError: Permission denied to access property "windowGlobalChild" on cross-origin object
[task 2023-10-02T00:44:13.744Z] 00:44:13     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | took 326621ms

Comment 1

[Intermittent Failures Robot]

2 failures in 3726 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1856265&startday=2023-09-25&endday=2023-10-01&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 4018 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1856265&startday=2023-10-02&endday=2023-10-08&tree=all

Comment 3

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

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

Comment 4

[Iulian Moraru]

This started failing on tier 1: https://treeherder.mozilla.org/logviewer?job_id=458213627&repo=mozilla-central&lineNumber=7493

Comment 5

[Intermittent Failures Robot]

1 failures in 4547 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1856265&startday=2024-05-13&endday=2024-05-19&tree=all

Comment 6

[Intermittent Failures Robot]

1 failures in 4202 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1856265&startday=2024-05-27&endday=2024-06-02&tree=all

Comment 7

[Rob Wu [:robwu]]

Relevant log from comment 6; note that it ends with TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | message queue is empty - got "[\"background-ready\"]", expected "[]", which is a sign that the background script (of the event page) has started twice (sent from https://searchfox.org/mozilla-central/rev/d3fea1aa852bb3a353a0a4a875c3685da11ce39b/toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html#108).

[task 2024-05-28T11:29:31.428Z] 11:29:31     INFO - Buffered messages logged at 11:28:37
[task 2024-05-28T11:29:31.428Z] 11:29:31     INFO - add_task | Entering setup
[task 2024-05-28T11:29:31.428Z] 11:29:31     INFO - add_task | Leaving setup
[task 2024-05-28T11:29:31.429Z] 11:29:31     INFO - add_task | Entering test_executeScript_activeTab_permission
[task 2024-05-28T11:29:31.431Z] 11:29:31     INFO - Extension loaded
[task 2024-05-28T11:29:31.431Z] 11:29:31     INFO - Buffered messages logged at 11:29:23
[task 2024-05-28T11:29:31.431Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected number of results - Expected: 1, Actual: 1 
[task 2024-05-28T11:29:31.431Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got the expected title - Expected: file sample, Actual: file sample 
[task 2024-05-28T11:29:31.431Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got the expected frameId - Expected: 0, Actual: 0 
[task 2024-05-28T11:29:31.432Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 140, Actual: 140 
[task 2024-05-28T11:29:31.433Z] 11:29:31     INFO - Buffered messages logged at 11:29:24
[task 2024-05-28T11:29:31.433Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 140, Actual: 140 
[task 2024-05-28T11:29:31.435Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 140, Actual: 140 
[task 2024-05-28T11:29:31.435Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 140, Actual: 140 
[task 2024-05-28T11:29:31.436Z] 11:29:31     INFO - Buffered messages logged at 11:29:25
[task 2024-05-28T11:29:31.437Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | Promise rejected, expecting rejection to match '"Missing host permission for the tab"', got 'Error: Missing host permission for the tab': expected host permission error 
[task 2024-05-28T11:29:31.438Z] 11:29:31     INFO - add_task | Leaving test_executeScript_activeTab_permission
[task 2024-05-28T11:29:31.438Z] 11:29:31     INFO - add_task | Entering test_executeScript_activeTab_automatic_originControls
[task 2024-05-28T11:29:31.439Z] 11:29:31     INFO - Extension loaded
[task 2024-05-28T11:29:31.439Z] 11:29:31     INFO - Buffered messages logged at 11:29:29
[task 2024-05-28T11:29:31.455Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected number of results - Expected: 1, Actual: 1 
[task 2024-05-28T11:29:31.456Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got the expected title - Expected: file sample, Actual: file sample 
[task 2024-05-28T11:29:31.457Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got the expected frameId - Expected: 0, Actual: 0 
[task 2024-05-28T11:29:31.458Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 141, Actual: 141 
[task 2024-05-28T11:29:31.458Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 141, Actual: 141 
[task 2024-05-28T11:29:31.459Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 141, Actual: 141 
[task 2024-05-28T11:29:31.460Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | got expected tabId - Expected: 141, Actual: 141 
[task 2024-05-28T11:29:31.461Z] 11:29:31     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | Promise rejected, expecting rejection to match '"Missing host permission for the tab"', got 'Error: Missing host permission for the tab': expected host permission error 
[task 2024-05-28T11:29:31.461Z] 11:29:31     INFO - Buffered messages logged at 11:29:30
[task 2024-05-28T11:29:31.461Z] 11:29:31     INFO - add_task | Leaving test_executeScript_activeTab_automatic_originControls
[task 2024-05-28T11:29:31.462Z] 11:29:31     INFO - Buffered messages finished
[task 2024-05-28T11:29:31.464Z] 11:29:31     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html | message queue is empty - got "[\"background-ready\"]", expected "[]"
[task 2024-05-28T11:29:31.464Z] 11:29:31     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:509:14
[task 2024-05-28T11:29:31.464Z] 11:29:31     INFO -     ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:47:18
[task 2024-05-28T11:29:31.464Z] 11:29:31     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1568:13
[task 2024-05-28T11:29:31.488Z] 11:29:31     INFO - GECKO(7274) | MEMORY STAT | vsize 20974761MB | residentFast 711MB
[task 2024-05-28T11:29:31.489Z] 11:29:31    ERROR - TEST-UNEXPECTED-FAIL | /tests/toolkit/components/extensions/test/mochitest/test_ext_scripting_executeScript_activeTab.html logged result after SimpleTest.finish(): message queue is empty

Comment 8

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

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