Closed Bug 1651274 Opened 4 years ago Closed 4 years ago

Intermittent toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | content-0.27492642530217537 rejected with Actor 'Conduits' destroyed before query was resolved

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(firefox80 fixed, firefox81 fixed)

RESOLVED FIXED
81 Branch
Tracking Status
firefox80 --- fixed
firefox81 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:1655624])

Attachments

(2 obsolete files)

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


[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage1@mochitest.mozilla.org: sender url correct
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - Buffered messages finished
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | content-0.27492642530217537 rejected with Actor 'Conduits' destroyed before query was resolved
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:409:16
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - testHandler@SimpleTest/ExtensionTestUtils.js:72:18
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - testResult@SimpleTest/ExtensionTestUtils.js:82:18
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage2@mochitest.mozilla.org: Correct content script external response token - Expected: sendmessage2@mochitest.mozilla.org-done, Actual: sendmessage2@mochitest.mozilla.org-done
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage2@mochitest.mozilla.org: Got content script message
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:409:16
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - testHandler@SimpleTest/ExtensionTestUtils.js:72:18
[task 2020-07-08T02:25:34.478Z] 02:25:34 INFO - testResult@SimpleTest/ExtensionTestUtils.js:82:18
[task 2020-07-08T02:25:34.479Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage2@mochitest.mozilla.org: Got expected sender ID - Expected: sendmessage2@mochitest.mozilla.org, Actual: sendmessage2@mochitest.mozilla.org
[task 2020-07-08T02:25:34.479Z] 02:25:34 INFO - GECKO(8864) | Console message: [JavaScript Error: "Error: Actor 'Conduits' destroyed before query was resolved" {file: "moz-extension://0211565a-f49e-4475-9fcf-caf071c97315/content_script.js" line: 14}]
[task 2020-07-08T02:25:34.479Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage2@mochitest.mozilla.org: Correct content script message - Expected: 0.27492642530217537-contentMessage, Actual: 0.27492642530217537-contentMessage
[task 2020-07-08T02:25:34.479Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage1@mochitest.mozilla.org: Got expected sender ID - Expected: sendmessage1@mochitest.mozilla.org, Actual: sendmessage1@mochitest.mozilla.org
[task 2020-07-08T02:25:34.479Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage1@mochitest.mozilla.org: Correct content script message - Expected: 0.6313981169762939-contentMessage, Actual: 0.6313981169762939-contentMessage
[task 2020-07-08T02:25:34.479Z] 02:25:34 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | sendmessage1@mochitest.mozilla.org: Correct content script response token - Expected: 0.6313981169762939-done, Actual: 0.6313981169762939-done
[task 2020-07-08T02:30:32.952Z] 02:30:32 INFO - GECKO(8864) | Console message: [JavaScript Error: "Unknown Collection "main/messaging-experiments"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 158}]
[task 2020-07-08T02:30:32.952Z] 02:30:32 INFO - GECKO(8864) | UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:158:5
[task 2020-07-08T02:30:32.952Z] 02:30:32 INFO - GECKO(8864) | sync@resource://services-settings/RemoteSettingsClient.jsm:433:13
[task 2020-07-08T02:30:36.780Z] 02:30:36 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-08T02:30:36.780Z] 02:30:36 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | Test timed out.
[task 2020-07-08T02:30:36.780Z] 02:30:36 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:409:16
[task 2020-07-08T02:30:36.780Z] 02:30:36 INFO - reportError@SimpleTest/TestRunner.js:138:22
[task 2020-07-08T02:30:36.780Z] 02:30:36 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:160:18
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | Extension left running at test shutdown
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:409:16
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:117:18
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1584:13
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1598:3
[task 2020-07-08T02:30:37.778Z] 02:30:37 INFO - killTest@SimpleTest/TestRunner.js:147:22
[task 2020-07-08T02:30:37.816Z] 02:30:37 INFO - GECKO(8864) | Console message: Warning: attempting to write 8223 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 2020-07-08T02:30:37.846Z] 02:30:37 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-08T02:30:37.846Z] 02:30:37 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_sendmessage_reply2.html | Extension left running at test shutdown
[task 2020-07-08T02:30:37.846Z] 02:30:37 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:409:16
[task 2020-07-08T02:30:37.846Z] 02:30:37 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:117:18
[task 2020-07-08T02:30:37.846Z] 02:30:37 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1584:13
[task 2020-07-08T02:30:37.847Z] 02:30:37 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1594:7
[task 2020-07-08T02:30:37.872Z] 02:30:37 INFO - GECKO(8864) | Console message: Warning: attempting to write 8147 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 2020-07-08T02:30:37.872Z] 02:30:37 INFO - Not taking screenshot here: see the one that was previously logged

In the last 7 days there are 82 failures.
Linux - 64 failures
Windows 10 - 16 failures
Windows 7 - 1 failure
Macosx1014 - 1 failure

I`ll add a disable patch for linux1804-64

Flags: needinfo?(mixedpuppy)
Assignee: nobody → nbeleuzu
Status: NEW → ASSIGNED
Attachment #9166048 - Attachment description: Bug 1651274 - Disable test_ext_sendmessage_reply2.html on Linux1804-64. r?#intermittent-reviewers → Bug 1651274 - Disable test_ext_sendmessage_reply2.html on linux1804-64 and windows10-64. r?#intermittent-reviewers

The error Actor 'Conduits' destroyed before query was resolved has been introduced recently by Bug 1650837.

I guess that the same condition was likely be happening even before Bug 1650837 and it may be just started to log it explicitly, but given that this failure started to intermittently pretty frequently and it is going to be disabled on some of the builds (the attached patch is going to skip it on linux64 and win64) it seems something that may be worth to take a look into and see if it is something that may just have to be fix in the test (or if it show us something that the implementation should be deal with it).

Tomislav, is this already under your radar? if it is not, would you mind to take a look?

Flags: needinfo?(mixedpuppy) → needinfo?(tomica)

Rob did mention in the phabricator revision that he is going to push a patch to fix the issue and ask a review from Tomislav, and so I'm redirecting the needinfo to Rob to reflect that on bugzilla.

Flags: needinfo?(tomica) → needinfo?(rob)

The test opens a tab, and runs two extensions in that tab. Both extensions exchange extension messages, and at the end of the test, the script calls window.close() and sends a message to the test runner to signal completion.

In the past, all extension messages went through the same internals, and there was enough time to process the messages before the tab was closed.
When the logic was migrated to actors, I guess that the messages of independent extensions weren't necessarily ordered any more, and it was possible for one extension to finish, and the tab to be closed before the other extension has had a chance to send its message to the extension.

Extension messages sent prior to closing a tab should be processed, and that is already covered by https://searchfox.org/mozilla-central/source/toolkit/components/extensions/test/xpcshell/test_ext_unload_frame.js .

I'm going to fix this by delaying the tab removal until the end of the test.

Assignee: nbeleuzu → rob
Flags: needinfo?(rob)

There is already a win.close() call at the end of the test, there is
no need to call it earlier. In fact, calling it earlier may cause
intermittent test failures because the test runs two extensions in
parallel, and closing a tab early can cause the test to be stuck due to
the early close.

Rob, is there any chance that Bug 1651535 (another intermittent tracked for the same test file) could also be related to the same root cause described in comment 14?

Flags: needinfo?(rob)
Flags: needinfo?(rob)
Depends on: 1655624
Attachment #9166281 - Attachment is obsolete: true

There is a patch up for review that should land next week. Removing the disable tag.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Whiteboard: [stockwell disable-recommended]
Whiteboard: [stockwell disable-recommended] → [comment 22]

In the last 7 days there have been 94 occurrences, most on linux1804-64, some on windows10-64 opt and debug.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=312512393&repo=autoland&lineNumber=7597

The patch on bug 1655624 has received a blocking review.

Whiteboard: [comment 22] → [comment 22][stockwell needswork:owner]
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Whiteboard: [comment 22][stockwell disable-recommended] → [stockwell fixed:1655624]
Target Milestone: --- → 81 Branch
Attachment #9166048 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: