Closed Bug 1642115 Opened 4 years ago Closed 2 years ago

Perma [tier2][TC] toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out.

Categories

(Testing :: Code Coverage, defect)

defect
Not set
normal

Tracking

(firefox-esr68 unaffected, firefox77 unaffected, firefox78 affected, firefox79 affected)

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

Regressed by: 1641269
Summary: Intermittent [tier2][TC] toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out. → Perma [tier2][TC] toolkit/components/extensions/test/mochitest/test_ext_webrequest_and_proxy_filter.html | Test timed out.

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.

Component: Request Handling → Code Coverage
Priority: P5 → --
Product: WebExtensions → Testing

Set release status flags based on info from the regressing bug 1641269

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.

Flags: needinfo?(klahnakoski)

:calixte Can I send these coverage crashes to you?

Flags: needinfo?(cdenizet)

I wonder if it could be a dup of bug 1637377.
So we can wait few more weeks to see if it still happens.

Flags: needinfo?(cdenizet)

Clear a needinfo that is pending on an inactive user.

For more information, please visit auto_nag documentation.

Flags: needinfo?(klahnakoski)

The intermittent failure doesn't exist anymore so I think we can close this bug.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.