Closed Bug 1642444 Opened 5 years ago Closed 4 years ago

Intermittent browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js | Test timed out -

Categories

(WebExtensions :: Untriaged, defect, P5)

Product:
WebExtensions
Component:
Untriaged
Type:
defect

Tracking

(firefox91 fixed)

Status:
RESOLVED FIXED
Milestone:
91 Branch
Tracking Flags:
Tracking Status
firefox91 --- fixed

People

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

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1642444 - Fix intermittent failures triggered by browser_ext_tabs_executeScript.js. r?mixedpuppy!
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2020-06-01T19:21:31.146Z] 19:21:31 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js
[task 2020-06-01T19:22:16.659Z] 19:22:16 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js | Got expected error - Expected: Missing host permission for the tab, Actual: Missing host permission for the tab -
[task 2020-06-01T19:22:16.660Z] 19:22:16 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js | Script executed correctly in new tab - Expected: http://example.com/, Actual: http://example.com/ -
[task 2020-06-01T19:22:16.661Z] 19:22:16 INFO - Buffered messages finished
[task 2020-06-01T19:22:16.661Z] 19:22:16 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js | Test timed out -
[task 2020-06-01T19:22:16.662Z] 19:22:16 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-06-01T19:22:16.663Z] 19:22:16 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js | Extension left running at test shutdown -
[task 2020-06-01T19:22:16.663Z] 19:22:16 INFO - Stack trace:
[task 2020-06-01T19:22:16.663Z] 19:22:16 INFO - chrome://mochikit/content/browser-test.js:test_ok:1299
[task 2020-06-01T19:22:16.664Z] 19:22:16 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:117
[task 2020-06-01T19:22:16.664Z] 19:22:16 INFO - chrome://mochikit/content/browser-test.js:nextTest:550
[task 2020-06-01T19:22:16.665Z] 19:22:16 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1190
[task 2020-06-01T19:22:16.666Z] 19:22:16 INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1137
[task 2020-06-01T19:22:16.666Z] 19:22:16 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-06-01T19:22:16.666Z] 19:22:16 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-06-01T19:22:16.667Z] 19:22:16 INFO - GECKO(5889) | MEMORY STAT | vsize 3882MB | residentFast 556MB | heapAllocated 187MB
[task 2020-06-01T19:22:16.668Z] 19:22:16 INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_tabs_executeScript.js | took 45050ms
[task 2020-06-01T19:22:16.668Z] 19:22:16 INFO - Not taking screenshot here: see the one that was previously logged

I was unable to reproduce this locally, but looking to the logs from the failures tracked by this bug
I did notice this logged error which suspiciously point in the direction of a race between registering
a browser.runtime.onMessage listener and sending a message to that listener from the content script "script.js":

Console message: [JavaScript Error: "Error: Could not establish connection. Receiving end does not exist."
                 {file: "moz-extension://f0d0d3ec-6815-4d78-aa83-3516814353a2/script.js" line: 2}]

Both the browser.tabs.executeScript that will run "script.js" and the promise that registers the browser.runtime.onMessage
listener are part of a single Promise.all call, but the browser.tabs.executeScript is technically listed before the
promise that registers the browser.runtime.onMessage. I think that in most cases this isn't a problem and the
listener is already registered when the content script is being executed, but that may not be always the case and
intermittently the content script may have been executed earlier while the browser.runtime.onMessage listener was
not already registered (and the test will get stuck, because that promise will never resolves).

To double-check this rationale, I tried to recreate the issue by introducing a delay inside that Promise and
that was triggering the exact set of logged message and failure.

This patch just change the order of those two promise, making sure that the browser.runtime.onMessage will be registered
by the time the content script is going to be executed.

Assignee: nobody → lgreco
Status: NEW → ASSIGNED
Pushed by luca.greco@alcacoop.it: https://hg.mozilla.org/integration/autoland/rev/77f16565a279 Fix intermittent failures triggered by browser_ext_tabs_executeScript.js. r=mixedpuppy
Pushed by nbeleuzu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/26a3dbd28011 Fix intermittent failures triggered by browser_ext_tabs_executeScript.js. r=mixedpuppy CLOSED TREE
Backout by nbeleuzu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/8b6439a7df0d Backed out changeset 77f16565a279 for WP failures on iframe-cross-origin-print.sub.html CLOSED TREE

https://hg.mozilla.org/mozilla-central/rev/26a3dbd28011

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox91: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 91 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: