Closed Bug 1633189 Opened 5 years ago Closed 2 months ago

Intermittent toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html | Test timed out.

Categories

(WebExtensions :: General, defect, P3)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

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 handler
TestRunner._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 handler
TestRunner._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 handler
TestRunner._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 handler
TestRunner._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 handler
TestRunner._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 callback
TestRunner.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.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Has Regression Range: --- → yes

The patch just removed unused listening API:

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.

Flags: needinfo?(masayuki) → needinfo?(mixedpuppy)
[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.

Assignee: nobody → mixedpuppy

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.

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

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?

Flags: needinfo?(mixedpuppy)
Whiteboard: [retriggered][stockwell unknown] → [retriggered][stockwell needswork:owner]

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.

Flags: needinfo?(mixedpuppy)

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.

Flags: needinfo?(mixedpuppy)
Severity: normal → S3
Pushed by scaraveo@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f7f5e7f11445 address intermittent cache request failures with style sheets in webrequest test r=masayuki

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.

Flags: needinfo?(jmuizelaar)

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?

Flags: needinfo?(mixedpuppy)
Flags: needinfo?(jmuizelaar)
Flags: needinfo?(mixedpuppy)

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
Whiteboard: [retriggered][stockwell unknown] → [retriggered][stockwell needswork:owner]

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).

See Also: → 1694939, 1657575
Assignee: mixedpuppy → rob
Status: REOPENED → ASSIGNED
Flags: needinfo?(mixedpuppy)
Priority: P5 → P3
Keywords: leave-open
Whiteboard: [retriggered][stockwell needswork:owner] → [retriggered][stockwell needswork:owner][stockwell disabled]
Attachment #9237480 - Attachment description: Bug 1633189 - Disable toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html for frequent linux-asan-opt failures. r=#intermittent-reviewers → Bug 1633189 - disable toolkit/components/extensions/test/mochitest/test_ext_webrequest_basic.html for frequent linux-asan-opt failures. r=#intermittent-reviewers

Marking comment above as obsolete. Moving ni request to Bug 1733781

Flags: needinfo?(lgreco)
Status: ASSIGNED → RESOLVED
Closed: 5 years ago2 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: