Perma [tier2][TC] toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out.
Categories
(Testing :: Code Coverage, defect)
Tracking
(firefox-esr68 unaffected, firefox77 unaffected, firefox78 affected, firefox79 affected)
Tracking | Status | |
---|---|---|
firefox-esr68 | --- | unaffected |
firefox77 | --- | unaffected |
firefox78 | --- | affected |
firefox79 | --- | affected |
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Regression)
Details
(Keywords: intermittent-failure, regression)
Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=304383468&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YymaGt7-QtCxFy6DME7Spw/runs/0/artifacts/public/logs/live_backing.log
[task 2020-05-30T11:13:48.011Z] 11:13:48 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html
[task 2020-05-30T11:13:48.409Z] 11:13:48 INFO - GECKO(24678) | Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "moz-extension://a12fc87c-d094-41a5-8b74-46de90fc12f1/tab.html" line: 0}]
[task 2020-05-30T11:13:48.612Z] 11:13:48 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24678.
[task 2020-05-30T11:13:48.808Z] 11:13:48 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:13:49.346Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:13:49.346Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24767.
[task 2020-05-30T11:13:49.346Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24854.
[task 2020-05-30T11:13:49.347Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24783.
[task 2020-05-30T11:13:49.588Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:13:49.603Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:13:49.804Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:13:49.928Z] 11:13:49 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:13:50.124Z] 11:13:50 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:13:50.184Z] 11:13:50 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:13:50.188Z] 11:13:50 INFO - GECKO(24678) | 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-05-30T11:19:14.341Z] 11:19:14 INFO - TEST-INFO | started process screentopng
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - TEST-INFO | screentopng: exit 0
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Buffered messages logged at 11:13:48
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - add_task | Entering test test_filter_tabId_and_windowId
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Extension loaded
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Dummy tab has: tabId=3 windowId=1
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Triggering request from background page.
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Triggering request from tab.
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | got all events - Expected: 0, Actual: 0
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - add_task | Leaving test test_filter_tabId_and_windowId
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - Buffered messages finished
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out.
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - reportError@SimpleTest/TestRunner.js:128:22
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:18
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:420:16
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:407:48
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - RunSet.runtests@SimpleTest/setup.js:218:14
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - RunSet.runall@SimpleTest/setup.js:197:12
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - hookupTests@SimpleTest/setup.js:294:12
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:46:13
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:59:28
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:55:3
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - hookup@SimpleTest/setup.js:270:20
[task 2020-05-30T11:19:14.479Z] 11:19:14 INFO - EventHandlerNonNull@toolkit/components/extensions/test/mochitest?autorun=1&closeWhenDone=1&consoleLevel=INFO&testname=tests/toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2020-05-30T11:19:15.337Z] 11:19:15 ERROR - [SimpleTest.finish()] this test already called finish!
[task 2020-05-30T11:19:15.341Z] 11:19:15 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24678.
[task 2020-05-30T11:19:15.543Z] 11:19:15 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:19:16.060Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:19:16.063Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24783.
[task 2020-05-30T11:19:16.064Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24854.
[task 2020-05-30T11:19:16.064Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24767.
[task 2020-05-30T11:19:16.260Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:19:16.315Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:19:16.511Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:19:16.527Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:19:16.723Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] flush completed.
[task 2020-05-30T11:19:16.844Z] 11:19:16 INFO - GECKO(24678) | [CodeCoverage] JS flush completed.
[task 2020-05-30T11:19:16.845Z] 11:19:16 INFO - GECKO(24678) | 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-05-30T11:19:44.345Z] 11:19:44 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-30T11:19:44.345Z] 11:19:44 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out.
Updated•4 years ago
|
Comment 1•4 years ago
|
||
The test itself completes successfully. This looks like an issue with the code coverage system: the beforeTestSync
hook throws and interrupts the test execution. The error of interest is:
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]
The bug summary should probably be replaced with that, but I'll kick it over to the Code Coverage component first and let them check.
A dissection of the log follows below.
[task 2020-05-30T11:13:42.668Z] 11:13:42 INFO - SimpleTest START
[task 2020-05-30T11:13:42.695Z] 11:13:42 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24678.
(... etc more flush ...)
= from beforeTest
hook
[task 2020-05-30T11:13:44.331Z] 11:13:44 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html
[task 2020-05-30T11:13:46.097Z] 11:13:46 INFO - GECKO(24678) | Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "moz-extension://f7e68b43-f056-4a1d-8845-56164c28170f/tab.html" line: 0}]
= test started to run
[task 2020-05-30T11:13:46.347Z] 11:13:46 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24678.
(... etc more flush ...)
= from afterSyncTest
hook.
[task 2020-05-30T11:13:47.936Z] 11:13:47 INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | took 3599ms
= Test completion reported to test runner.
[task 2020-05-30T11:13:48.011Z] 11:13:48 INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html
[task 2020-05-30T11:13:48.409Z] 11:13:48 INFO - GECKO(24678) | Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "moz-extension://a12fc87c-d094-41a5-8b74-46de90fc12f1/tab.html" line: 0}]
= Test started again. I wonder why? The test is listed in mochitest-common.ini
and included by two different test manifests (mochitest.ini
and mochitest-remote.ini
), but that shouldn't run consecutively without flipping some preferences (because these two test manifests have some specific preferences). In the test log, I see that test is run again without setting a preference.
[task 2020-05-30T11:13:48.612Z] 11:13:48 INFO - GECKO(24678) | [CodeCoverage] Requested flush for 24678.
(... etc more flush ...)
[task 2020-05-30T11:13:50.188Z] 11:13:50 INFO - GECKO(24678) | 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]
= beforeTest
hook again. But one of the the moveDirectoryContents
calls throws.
That errors is thrown by beforeTestSync
, and consequently the test runner is stuck and won't continue with the next test: https://searchfox.org/mozilla-central/rev/8827278483c337667cdfb238112eb1be397dd102/testing/mochitest/browser-test.js#328
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Buffered messages logged at 11:13:48
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - add_task | Entering test test_filter_tabId_and_windowId
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Extension loaded
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Dummy tab has: tabId=3 windowId=1
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Triggering request from background page.
[task 2020-05-30T11:19:14.477Z] 11:19:14 INFO - Triggering request from tab.
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | got all events - Expected: 0, Actual: 0
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - add_task | Leaving test test_filter_tabId_and_windowId
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - Buffered messages finished
= Shows that the test successfully completed.
[task 2020-05-30T11:19:14.478Z] 11:19:14 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out.
Test timed out, but that's no surprise considering my previous observation that the test runner was interrupted.
Comment hidden (Intermittent Failures Robot) |
Comment 3•4 years ago
|
||
Set release status flags based on info from the regressing bug 1641269
Comment 5•4 years ago
|
||
Kyle, could you take a look at the analysis from comment 1? CodeCov is causing test failures due to what seems to be a bug in CodeCov instrumentation.
Comment 6•4 years ago
|
||
:calixte Can I send these coverage crashes to you?
Comment 7•4 years ago
•
|
||
I wonder if it could be a dup of bug 1637377.
So we can wait few more weeks to see if it still happens.
Comment 8•2 years ago
|
||
Clear a needinfo that is pending on an inactive user.
For more information, please visit auto_nag documentation.
Comment 9•2 years ago
|
||
The intermittent failure doesn't exist anymore so I think we can close this bug.
Updated•2 years ago
|
Description
•