Intermittent toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out.
Categories
(WebExtensions :: General, defect, P3)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Assigned: robwu)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell unknown])
Attachments
(2 files)
Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=299393245&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/PkaNM2JmT5yLso9vyDWv_w/runs/0/artifacts/public/logs/live_backing.log
[task 2020-04-25T11:29:59.123Z] 11:29:59 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2020-04-25T11:30:00.525Z] 11:30:00 INFO - GECKO(29867) | Console message: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_script_bad.js”." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html" line: 1}]
[task 2020-04-25T11:30:00.785Z] 11:30:00 INFO - GECKO(29867) | Console message: [JavaScript Warning: "Synchronous XMLHttpRequest on the main thread is deprecated because of its detrimental effects to the end user’s experience. For more help http://xhr.spec.whatwg.org/" {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_script_xhr.js" line: 4}]
[task 2020-04-25T11:30:00.983Z] 11:30:00 INFO - GECKO(29867) | Console message: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/nonexistent_script_url.js”." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html" line: 1}]
[task 2020-04-25T11:30:01.322Z] 11:30:01 INFO - GECKO(29867) | Console message: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/nonexistent_script_url.js”." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html" line: 1}]
[task 2020-04-25T11:30:01.479Z] 11:30:01 INFO - GECKO(29867) | Console message: [JavaScript Warning: "Loading failed for the <script> with source “http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_script_nonexistent.js”." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html" line: 1}]
[task 2020-04-25T11:30:03.833Z] 11:30:03 INFO - GECKO(29867) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-04-25T11:30:04.354Z] 11:30:04 INFO - GECKO(29867) | [CodeCoverage] Setting handlers for process 30207.
[task 2020-04-25T11:30:05.244Z] 11:30:05 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 29867.
[task 2020-04-25T11:30:05.522Z] 11:30:05 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:30:06.196Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:30:06.196Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 30047.
[task 2020-04-25T11:30:06.196Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 30207.
[task 2020-04-25T11:30:06.198Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 30031.
[task 2020-04-25T11:30:06.461Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:30:06.485Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:30:06.768Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:30:06.836Z] 11:30:06 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:30:07.127Z] 11:30:07 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:30:07.288Z] 11:30:07 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:30:07.292Z] 11:30:07 INFO - GECKO(29867) | JavaScript error: resource://testing-common/PerTestCoverageUtils.jsm, line 76: NS_ERROR_FILE_DIR_NOT_EMPTY: Component returned failure code: 0x80520014 (NS_ERROR_FILE_DIR_NOT_EMPTY) [nsIFile.moveTo]
[task 2020-04-25T11:35:18.745Z] 11:35:18 INFO - TEST-INFO | started process screentopng
[task 2020-04-25T11:35:18.923Z] 11:35:18 INFO - TEST-INFO | screentopng: exit 0
[task 2020-04-25T11:35:18.925Z] 11:35:18 INFO - <snipped 786 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2020-04-25T11:35:18.927Z] 11:35:18 INFO - Buffered messages logged at 11:30:04
[task 2020-04-25T11:35:18.928Z] 11:35:18 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | valid resource type sub_frame
[task 2020-04-25T11:35:18.992Z] 11:35:18 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | User-Agent header matched and changed.
[task 2020-04-25T11:35:18.992Z] 11:35:18 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | User-Agent header blindly added.
[task 2020-04-25T11:35:18.994Z] 11:35:18 INFO - add_task | Leaving test test_case_preserving
[task 2020-04-25T11:35:18.994Z] 11:35:18 INFO - Buffered messages finished
[task 2020-04-25T11:35:18.996Z] 11:35:18 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out.
[task 2020-04-25T11:35:18.996Z] 11:35:18 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
[task 2020-04-25T11:35:18.996Z] 11:35:18 INFO - reportError@SimpleTest/TestRunner.js:128:22
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:18
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.997Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:420:16
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:407:48
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - RunSet.runtests@SimpleTest/setup.js:218:14
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - RunSet.runall@SimpleTest/setup.js:197:12
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - hookupTests@SimpleTest/setup.js:294:12
[task 2020-04-25T11:35:18.998Z] 11:35:18 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:46:13
[task 2020-04-25T11:35:18.999Z] 11:35:18 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:59:28
[task 2020-04-25T11:35:18.999Z] 11:35:18 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:55:3
[task 2020-04-25T11:35:18.999Z] 11:35:18 INFO - hookup@SimpleTest/setup.js:270:20
[task 2020-04-25T11:35:18.999Z] 11:35:18 INFO - EventHandlerNonNull@toolkit/components/extensions/test/mochitest?autorun=1&closeWhenDone=1&consoleLevel=INFO&testname=tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2020-04-25T11:35:19.745Z] 11:35:19 ERROR - [SimpleTest.finish()] this test already called finish!
[task 2020-04-25T11:35:19.753Z] 11:35:19 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 29867.
[task 2020-04-25T11:35:20.035Z] 11:35:20 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:35:20.689Z] 11:35:20 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:35:20.689Z] 11:35:20 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 30031.
[task 2020-04-25T11:35:20.690Z] 11:35:20 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 30047.
[task 2020-04-25T11:35:20.690Z] 11:35:20 INFO - GECKO(29867) | [CodeCoverage] Requested flush for 30207.
[task 2020-04-25T11:35:20.968Z] 11:35:20 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:35:21.036Z] 11:35:21 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:35:21.323Z] 11:35:21 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:35:21.488Z] 11:35:21 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:35:21.766Z] 11:35:21 INFO - GECKO(29867) | [CodeCoverage] flush completed.
[task 2020-04-25T11:35:21.786Z] 11:35:21 INFO - GECKO(29867) | [CodeCoverage] JS flush completed.
[task 2020-04-25T11:35:21.794Z] 11:35:21 INFO - GECKO(29867) | JavaScript error: resource://testing-common/PerTestCoverageUtils.jsm, line 76: NS_ERROR_FILE_DIR_NOT_EMPTY: Component returned failure code: 0x80520014 (NS_ERROR_FILE_DIR_NOT_EMPTY) [nsIFile.moveTo]
[task 2020-04-25T11:35:48.745Z] 11:35:48 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-25T11:35:48.746Z] 11:35:48 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out.
Comment hidden (Intermittent Failures Robot) |
Comment 2•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment hidden (Intermittent Failures Robot) |
Comment 4•4 years ago
|
||
New occurrence:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=311485708&repo=autoland&lineNumber=15367
Comment 5•4 years ago
|
||
Masayuki, please take a look.
Updated•4 years ago
|
Comment 6•4 years ago
|
||
The patch just removed unused listening API:
- https://searchfox.org/mozilla-central/search?q=DidDeleteSelection&path=&case=false®exp=false
- https://searchfox.org/mozilla-central/search?q=DidSplitNode&path=&case=false®exp=false
- https://searchfox.org/mozilla-central/search?q=DidInsertNode&path=&case=false®exp=false
- https://searchfox.org/mozilla-central/search?q=DidCreateNode&path=&case=false®exp=false
Actually, there are no methods named as them except mozInlineSpecllChecker
, but it's just a same name method, not a part of nsIEditActionListener
. So, the patch might change some race condition due to dropping the loops notifying listeners.
And looks like the test is a suite of various testing. I'm not sure whether some of them touch editor or not yet. I'll keep checking, but according to the log, the test is really unstable and changed a lot of time. So, I'd like to ask the maintainer, mixedpuppy, what's going on here.
Comment 7•4 years ago
|
||
[task 2020-07-30T09:35:27.734Z] 09:35:27 INFO - onErrorOccurred 1176 http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_style_bad.css
[task 2020-07-30T09:35:27.734Z] 09:35:27 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | received onErrorOccurred
[task 2020-07-30T09:35:27.735Z] 09:35:27 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | resource type is correct - Expected: stylesheet, Actual: stylesheet
[task 2020-07-30T09:35:27.736Z] 09:35:27 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | origin is correct - Expected: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html, Actual: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2020-07-30T09:35:27.736Z] 09:35:27 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | correct requestId - Expected: 1176, Actual: 1176
[task 2020-07-30T09:35:27.736Z] 09:35:27 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | correct tabId - Expected: 1, Actual: 1
[task 2020-07-30T09:35:27.737Z] 09:35:27 INFO - Buffered messages finished
[task 2020-07-30T09:35:27.737Z] 09:35:27 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out.
[task 2020-07-30T09:35:27.737Z] 09:35:27 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:412:16
[task 2020-07-30T09:35:27.737Z] 09:35:27 INFO - reportError@SimpleTest/TestRunner.js:138:22
[task 2020-07-30T09:35:27.737Z] 09:35:27 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:160:18
[task 2020-07-30T09:35:28.560Z] 09:35:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-30T09:35:28.572Z] 09:35:28 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Extension left running at test shutdown
[task 2020-07-30T09:35:28.573Z] 09:35:28 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:412:16
[task 2020-07-30T09:35:28.573Z] 09:35:28 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:117:18
[task 2020-07-30T09:35:28.574Z] 09:35:28 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1587:13
[task 2020-07-30T09:35:28.574Z] 09:35:28 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1601:3
[task 2020-07-30T09:35:28.574Z] 09:35:28 INFO - killTest@SimpleTest/TestRunner.js:147:22
[task 2020-07-30T09:35:28.583Z] 09:35:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-30T09:35:28.583Z] 09:35:28 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | no tasks awaiting on messages - got "[\"done\"]", expected "[]"
[task 2020-07-30T09:35:28.583Z] 09:35:28 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:495:14
[task 2020-07-30T09:35:28.584Z] 09:35:28 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:36:18
[task 2020-07-30T09:35:28.584Z] 09:35:28 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1587:13
[task 2020-07-30T09:35:29.603Z] 09:35:29 INFO - GECKO(8448) | MEMORY STAT | vsize 2588MB | residentFast 174MB | heapAllocated 17MB
[task 2020-07-30T09:35:31.626Z] 09:35:31 INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | took 331021ms
[task 2020-07-30T09:35:34.632Z] 09:35:34 INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2020-07-30T09:35:34.660Z] 09:35:34 ERROR - /tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html logged result after SimpleTest.finish(): Extension left running at test shutdown
[task 2020-07-30T09:35:34.660Z] 09:35:34 ERROR - /tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html logged result after SimpleTest.finish(): no tasks awaiting on messages
Oh, there is an error message. It's here:
https://searchfox.org/mozilla-central/rev/03794edd6edcc3fc1e222de966cb27256ce08998/testing/mochitest/tests/SimpleTest/TestRunner.js#365
According to the message, Fission's focus handling is something changed before my landing or my patch just change the race condition in focused process.
Comment 8•4 years ago
|
||
Looks like the hang occurs here:
https://searchfox.org/mozilla-central/rev/03794edd6edcc3fc1e222de966cb27256ce08998/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html#81-84
Both stylesheets change only foreground color of #text
.
https://searchfox.org/mozilla-central/source/toolkit/components/extensions/test/mochitest/file_style_bad.css
https://searchfox.org/mozilla-central/source/toolkit/components/extensions/test/mochitest/file_style_redirect.css
"cancelled" message is sent from here:
https://searchfox.org/mozilla-central/rev/03794edd6edcc3fc1e222de966cb27256ce08998/toolkit/components/extensions/test/mochitest/head_webrequest.js#389
addStyleSheet()
modifies the DOM synchronously to add <link>
element to load the stylesheet.
https://searchfox.org/mozilla-central/rev/03794edd6edcc3fc1e222de966cb27256ce08998/toolkit/components/extensions/test/mochitest/head_webrequest.js#436-441
So, I guess that at this line: await extension.awaitMessage("cancelled");
, the load has already done in Fission world.
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 16•4 years ago
|
||
Updated•4 years ago
|
Comment 17•4 years ago
|
||
I just added a query param to avoid cache with a couple of the stylesheet tests. The rest of the patch change is the code formatter. Let me know if you're fine with this approach to avoid style sheet issues here.
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 22•4 years ago
|
||
There are 39 total failures in the last 7 days on linux1804-64-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=321669860&repo=autoland&lineNumber=6729
task 2020-11-13T06:37:39.373Z] 06:37:39 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2020-11-13T06:37:44.474Z] 06:37:44 INFO - GECKO(2890) | Console message: Warning: attempting to write 22227 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-11-13T06:40:39.712Z] 06:40:39 INFO - GECKO(2890) | 1605249639701 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates
[task 2020-11-13T06:40:39.713Z] 06:40:39 INFO - GECKO(2890) | Console message: [JavaScript Error: "1605249639701 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2020-11-13T06:40:39.714Z] 06:40:39 INFO - GECKO(2890) | append@resource://gre/modules/Log.jsm:723:12
[task 2020-11-13T06:40:39.714Z] 06:40:39 INFO - GECKO(2890) | log@resource://gre/modules/Log.jsm:379:16
[task 2020-11-13T06:40:39.714Z] 06:40:39 INFO - GECKO(2890) | error@resource://gre/modules/Log.jsm:387:10
[task 2020-11-13T06:40:39.715Z] 06:40:39 INFO - GECKO(2890) | updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4015:25
[task 2020-11-13T06:42:48.816Z] 06:42:48 INFO - TEST-INFO | started process screentopng
[task 2020-11-13T06:42:48.957Z] 06:42:48 INFO - TEST-INFO | screentopng: exit 0
[task 2020-11-13T06:42:48.959Z] 06:42:48 INFO - Buffered messages logged at 06:37:42
[task 2020-11-13T06:42:48.960Z] 06:42:48 INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2020-11-13T06:42:48.961Z] 06:42:48 INFO - Buffered messages logged at 06:37:43
[task 2020-11-13T06:42:48.961Z] 06:42:48 INFO - add_task | Entering test setup
[task 2020-11-13T06:42:48.961Z] 06:42:48 INFO - Buffered messages logged at 06:37:44
[task 2020-11-13T06:42:48.962Z] 06:42:48 INFO - Extension loaded
[task 2020-11-13T06:42:48.963Z] 06:42:48 INFO - adding listener for onBeforeRequest
[task 2020-11-13T06:42:48.963Z] 06:42:48 INFO - adding listener for onBeforeSendHeaders
[task 2020-11-13T06:42:48.964Z] 06:42:48 INFO - adding listener for onSendHeaders
[task 2020-11-13T06:42:48.964Z] 06:42:48 INFO - adding listener for onBeforeRedirect
[task 2020-11-13T06:42:48.964Z] 06:42:48 INFO - adding listener for onHeadersReceived
[task 2020-11-13T06:42:48.965Z] 06:42:48 INFO - adding listener for onResponseStarted
[task 2020-11-13T06:42:48.965Z] 06:42:48 INFO - adding listener for onCompleted
[task 2020-11-13T06:42:48.965Z] 06:42:48 INFO - adding listener for onErrorOccurred
[task 2020-11-13T06:42:48.966Z] 06:42:48 INFO - add_task | Leaving test setup
[task 2020-11-13T06:42:48.966Z] 06:42:48 INFO - add_task | Entering test test_webRequest_links
[task 2020-11-13T06:42:48.966Z] 06:42:48 INFO - onBeforeRequest 1321 http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_style_bad.css
[task 2020-11-13T06:42:48.966Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | received onBeforeRequest
[task 2020-11-13T06:42:48.967Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | resource type is correct - Expected: stylesheet, Actual: stylesheet
[task 2020-11-13T06:42:48.967Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | origin is correct - Expected: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html, Actual: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2020-11-13T06:42:48.969Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | tabId 1
[task 2020-11-13T06:42:48.969Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | requestId 1321
[task 2020-11-13T06:42:48.970Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | valid resource type stylesheet
[task 2020-11-13T06:42:48.970Z] 06:42:48 INFO - onBeforeRequest cancel request
[task 2020-11-13T06:42:48.971Z] 06:42:48 INFO - onErrorOccurred 1321 http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_style_bad.css
[task 2020-11-13T06:42:48.971Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | received onErrorOccurred
[task 2020-11-13T06:42:48.971Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | resource type is correct - Expected: stylesheet, Actual: stylesheet
[task 2020-11-13T06:42:48.973Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | origin is correct - Expected: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html, Actual: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2020-11-13T06:42:48.973Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | correct requestId - Expected: 1321, Actual: 1321
[task 2020-11-13T06:42:48.973Z] 06:42:48 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | correct tabId - Expected: 1, Actual: 1
[task 2020-11-13T06:42:48.974Z] 06:42:48 INFO - Buffered messages finished
[task 2020-11-13T06:42:48.974Z] 06:42:48 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out.
[task 2020-11-13T06:42:48.974Z] 06:42:48 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2020-11-13T06:42:48.974Z] 06:42:48 INFO - reportError@SimpleTest/TestRunner.js:143:22
[task 2020-11-13T06:42:48.975Z] 06:42:48 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:165:18
[task 2020-11-13T06:42:49.823Z] 06:42:49 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-13T06:42:49.824Z] 06:42:49 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Extension left running at test shutdown
[task 2020-11-13T06:42:49.824Z] 06:42:49 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2020-11-13T06:42:49.824Z] 06:42:49 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:117:18
[task 2020-11-13T06:42:49.824Z] 06:42:49 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1619:13
[task 2020-11-13T06:42:49.824Z] 06:42:49 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1633:3
[task 2020-11-13T06:42:49.825Z] 06:42:49 INFO - killTest@SimpleTest/TestRunner.js:152:22
[task 2020-11-13T06:42:49.831Z] 06:42:49 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-13T06:42:49.832Z] 06:42:49 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | no tasks awaiting on messages - got "["done"]", expected "[]"
[task 2020-11-13T06:42:49.832Z] 06:42:49 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2020-11-13T06:42:49.832Z] 06:42:49 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:36:18
[task 2020-11-13T06:42:49.833Z] 06:42:49 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1619:13
[task 2020-11-13T06:42:50.832Z] 06:42:50 INFO - GECKO(2890) | MEMORY STAT | vsize 2595MB | residentFast 155MB | heapAllocated 16MB
[task 2020-11-13T06:42:52.841Z] 06:42:52 INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | took 313468ms
[task 2020-11-13T06:42:55.848Z] 06:42:55 INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2020-11-13T06:42:55.851Z] 06:42:55 ERROR - TEST-UNEXPECTED-FAIL | /tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html logged result after SimpleTest.finish(): Extension left running at test shutdown
[task 2020-11-13T06:42:55.853Z] 06:42:55 ERROR - TEST-UNEXPECTED-FAIL | /tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html logged result after SimpleTest.finish(): no tasks awaiting on messages
Shane are there any updates here?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 27•4 years ago
|
||
There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:mixedpuppy, could you have a look please?
For more information, please visit auto_nag documentation.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 30•4 years ago
|
||
Shane, could you please take a look at these instances of Bug 1633189?
https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception%2Csuccess%2Crunning%2Cpending%2Crunnable&fromchange=1e0238293dea9dd83644ff46dca31c9046339dcb&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Copt%2Cmochitests%2Ctest-linux1804-64-qr%2Fopt-mochitest-plain-e10s%2C1&tochange=285f6a34e600b48b8fff0188f931dedf6729307f&selectedTaskRun=M0jdEaa1RmGN-i00pfGTbg.0
They seem to be permafailing on those two specific pushes and not on those who run all manifests.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 34•4 years ago
|
||
masayuki made a comment in review that caused me to pause on this, I haven't got around to looking back for a different way to handle this. If it gets worse I'll revisit.
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 hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment 46•3 years ago
|
||
Comment 47•3 years ago
|
||
Backed out for causing failures at test_ext_webrequest_basic.html.
Backout link: https://hg.mozilla.org/integration/autoland/rev/5d03a9d6cb8aeba1bb488b989712ad9cfa0546d2
Failure log: https://treeherder.mozilla.org/logviewer?job_id=340998028&repo=autoland&lineNumber=3605
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 52•3 years ago
|
||
https://hg.mozilla.org/integration/autoland/rev/16b06a2c00b0 turned this into a tier 2 perma-fail, treeherder link.
Jeff, could you have a look over this? Thank you.
Comment 53•3 years ago
|
||
https://hg.mozilla.org/integration/autoland/rev/16b06a2c00b0 is pretty unrelated to these tests and it's hard to imagine how it could've caused this to perma-fail other than by changing the timing.
Shane, based on the history in this bug, it seems like this test has issues. Should it just be disabled?
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 58•3 years ago
|
||
Update:
There have been 30 failures within the last 7 days:
• 26 failures on Linux 18.04 x64 WebRender asan opt
• 1 failures on Linux 18.04 x64 WebRender opt
• 1 failures on OS X 10.15 WebRender opt
• 2 failures on OS X 10.15 WebRender debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=349142097&repo=autoland&lineNumber=5801
[task 2021-08-21T18:03:10.091Z] 18:03:10 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2021-08-21T18:03:10.120Z] 18:03:10 INFO - GECKO(1877) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-21T18:03:10.121Z] 18:03:10 INFO - GECKO(1877) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-21T18:03:10.923Z] 18:03:10 INFO - GECKO(1877) | -----------------------------------------------------
[task 2021-08-21T18:03:10.924Z] 18:03:10 INFO - GECKO(1877) | Suppressions used:
[task 2021-08-21T18:03:10.925Z] 18:03:10 INFO - GECKO(1877) | count bytes template
[task 2021-08-21T18:03:10.926Z] 18:03:10 INFO - GECKO(1877) | 13 416 nsComponentManagerImpl
[task 2021-08-21T18:03:10.926Z] 18:03:10 INFO - GECKO(1877) | 2 288 libfontconfig.so
[task 2021-08-21T18:03:10.927Z] 18:03:10 INFO - GECKO(1877) | -----------------------------------------------------
[task 2021-08-21T18:03:14.325Z] 18:03:14 INFO - GECKO(1877) | Console message: Warning: attempting to write 22777 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 2021-08-21T18:08:20.615Z] 18:08:20 INFO - TEST-INFO | started process screentopng
[task 2021-08-21T18:08:20.790Z] 18:08:20 INFO - TEST-INFO | screentopng: exit 0
[task 2021-08-21T18:08:20.791Z] 18:08:20 INFO - Buffered messages logged at 18:03:13
[task 2021-08-21T18:08:20.793Z] 18:08:20 INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2021-08-21T18:08:20.794Z] 18:08:20 INFO - Buffered messages logged at 18:03:14
[task 2021-08-21T18:08:20.796Z] 18:08:20 INFO - add_task | Entering test setup
[task 2021-08-21T18:08:20.796Z] 18:08:20 INFO - Extension loaded
[task 2021-08-21T18:08:20.797Z] 18:08:20 INFO - adding listener for onBeforeRequest
[task 2021-08-21T18:08:20.797Z] 18:08:20 INFO - adding listener for onBeforeSendHeaders
[task 2021-08-21T18:08:20.797Z] 18:08:20 INFO - adding listener for onSendHeaders
[task 2021-08-21T18:08:20.798Z] 18:08:20 INFO - adding listener for onBeforeRedirect
[task 2021-08-21T18:08:20.798Z] 18:08:20 INFO - adding listener for onHeadersReceived
[task 2021-08-21T18:08:20.798Z] 18:08:20 INFO - adding listener for onResponseStarted
[task 2021-08-21T18:08:20.798Z] 18:08:20 INFO - adding listener for onCompleted
[task 2021-08-21T18:08:20.799Z] 18:08:20 INFO - adding listener for onErrorOccurred
[task 2021-08-21T18:08:20.799Z] 18:08:20 INFO - add_task | Leaving test setup
[task 2021-08-21T18:08:20.800Z] 18:08:20 INFO - add_task | Entering test test_webRequest_links
[task 2021-08-21T18:08:20.800Z] 18:08:20 INFO - onBeforeRequest 1740 http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_style_bad.css
[task 2021-08-21T18:08:20.802Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | received onBeforeRequest
[task 2021-08-21T18:08:20.802Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | resource type is correct - Expected: stylesheet, Actual: stylesheet
[task 2021-08-21T18:08:20.803Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | origin is correct - Expected: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html, Actual: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2021-08-21T18:08:20.803Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | tabId 1
[task 2021-08-21T18:08:20.804Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | requestId 1740
[task 2021-08-21T18:08:20.805Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | valid resource type stylesheet
[task 2021-08-21T18:08:20.805Z] 18:08:20 INFO - onBeforeRequest cancel request
[task 2021-08-21T18:08:20.806Z] 18:08:20 INFO - onErrorOccurred 1740 http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/file_style_bad.css
[task 2021-08-21T18:08:20.807Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | received onErrorOccurred
[task 2021-08-21T18:08:20.807Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | resource type is correct - Expected: stylesheet, Actual: stylesheet
[task 2021-08-21T18:08:20.807Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | origin is correct - Expected: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html, Actual: http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html
[task 2021-08-21T18:08:20.808Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | correct requestId - Expected: 1740, Actual: 1740
[task 2021-08-21T18:08:20.808Z] 18:08:20 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | correct tabId - Expected: 1, Actual: 1
[task 2021-08-21T18:08:20.808Z] 18:08:20 INFO - Buffered messages finished
[task 2021-08-21T18:08:20.808Z] 18:08:20 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out. -
[task 2021-08-21T18:08:21.634Z] 18:08:21 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-08-21T18:08:21.636Z] 18:08:21 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Extension left running at test shutdown
[task 2021-08-21T18:08:21.637Z] 18:08:21 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-08-21T18:08:21.637Z] 18:08:21 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:117:18
[task 2021-08-21T18:08:21.637Z] 18:08:21 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1487:13
[task 2021-08-21T18:08:21.637Z] 18:08:21 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1501:3
[task 2021-08-21T18:08:21.637Z] 18:08:21 INFO - killTest@SimpleTest/TestRunner.js:194:22
[task 2021-08-21T18:08:21.647Z] 18:08:21 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-08-21T18:08:21.647Z] 18:08:21 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | no tasks awaiting on messages - got "[\"done\"]", expected "[]"
[task 2021-08-21T18:08:21.648Z] 18:08:21 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-08-21T18:08:21.648Z] 18:08:21 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:36:18
[task 2021-08-21T18:08:21.648Z] 18:08:21 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1487:13
[task 2021-08-21T18:08:22.659Z] 18:08:22 INFO - GECKO(1877) | MEMORY STAT | vsize 20974639MB | residentFast 927MB
[task 2021-08-21T18:08:23.673Z] 18:08:23 INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | took 313581ms
[task 2021-08-21T18:08:26.679Z] 18:08:26 INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2021-08-21T18:08:26.701Z] 18:08:26 ERROR - TEST-UNEXPECTED-FAIL | /tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html logged result after SimpleTest.finish(): Extension left running at test shutdown
[task 2021-08-21T18:08:26.702Z] 18:08:26 ERROR - TEST-UNEXPECTED-FAIL | /tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html logged result after SimpleTest.finish(): no tasks awaiting on messages
[task 2021-08-21T18:08:26.734Z] 18:08:26 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_errors.html
Comment hidden (Intermittent Failures Robot) |
Comment 60•3 years ago
|
||
Assignee | ||
Comment 61•3 years ago
|
||
The specific failure of comment 58 is caused by the inability to detect a request for a CSS file, most likely because the file was already cached. The test could be fixed by wiping the stylesheet cache. I'm not sure why the ASAN build is more prone to this intermittent failure...
Possibly related: bug 1694939, bug 1657575 (maybe bug 1599160).
Assignee | ||
Updated•3 years ago
|
Updated•3 years ago
|
Updated•3 years ago
|
Comment 62•3 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (obsolete) |
Comment 67•3 years ago
|
||
Marking comment above as obsolete. Moving ni request to Bug 1733781
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 70•2 months ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Updated•2 months ago
|
Description
•