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)
Tracking
(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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 9•4 years ago
|
||
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
Comment 10•4 years ago
|
||
Updated•4 years ago
|
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 12•4 years ago
|
||
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?
Comment 13•4 years ago
|
||
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.
Assignee | ||
Comment 14•4 years ago
|
||
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 | ||
Comment 15•4 years ago
|
||
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.
Comment 16•4 years ago
|
||
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?
Assignee | ||
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 22•4 years ago
|
||
There is a patch up for review that should land next week. Removing the disable tag.
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment 29•4 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•4 years ago
|
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Description
•