1515967 - Intermittent toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html | Test timed out.

Status: RESOLVED DUPLICATE of bug 1516136

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: rgurzau [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=218352472&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/EHZPfI5_R5mGyH3SAXYZSQ/runs/0/artifacts/public/logs/live_backing.log

[task 2018-12-21T15:55:05.442Z] 15:55:05     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html
[task 2018-12-21T15:55:05.466Z] 15:55:05     INFO - GECKO(3136) | ++DOMWINDOW == 7 (0x7fcecdabe400) [pid = 3236] [serial = 7] [outer = 0x7fcece55c800]
[task 2018-12-21T15:55:06.554Z] 15:55:06     INFO - GECKO(3136) | ++DOMWINDOW == 8 (0x7fcecd6c8c00) [pid = 3236] [serial = 8] [outer = 0x7fcece55c800]
[task 2018-12-21T15:55:06.996Z] 15:55:06     INFO - GECKO(3136) | [Parent 3136, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2018-12-21T15:55:06.997Z] 15:55:06     INFO - GECKO(3136) | [Parent 3136, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2018-12-21T15:55:07.079Z] 15:55:07     INFO - GECKO(3136) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html" line: 0}]
[task 2018-12-21T15:55:07.262Z] 15:55:07     INFO - GECKO(3136) | [Parent 3136, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 318
[task 2018-12-21T15:55:07.307Z] 15:55:07     INFO - GECKO(3136) | ++DOCSHELL 0x7fdeef498800 == 5 [pid = 3136] [id = {2bf7f3c1-fcc6-466e-b87c-0062d3ae79b6}]
[task 2018-12-21T15:55:07.308Z] 15:55:07     INFO - GECKO(3136) | ++DOMWINDOW == 11 (0x7fdeeffe0c00) [pid = 3136] [serial = 11] [outer = (nil)]
[task 2018-12-21T15:55:07.392Z] 15:55:07     INFO - GECKO(3136) | ++DOMWINDOW == 12 (0x7fdeeffdb400) [pid = 3136] [serial = 12] [outer = 0x7fdeeffe0c00]
[task 2018-12-21T15:55:07.440Z] 15:55:07     INFO - GECKO(3136) | ++DOMWINDOW == 13 (0x7fdef0902800) [pid = 3136] [serial = 13] [outer = 0x7fdeeffe0c00]
[task 2018-12-21T15:55:07.848Z] 15:55:07     INFO - GECKO(3136) | [Parent 3136, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 318
[task 2018-12-21T15:55:07.889Z] 15:55:07     INFO - GECKO(3136) | ++DOCSHELL 0x7fdef0ee6000 == 6 [pid = 3136] [id = {07f1526e-2bf8-49ed-be8e-55b4ad52b19a}]
[task 2018-12-21T15:55:07.890Z] 15:55:07     INFO - GECKO(3136) | ++DOMWINDOW == 14 (0x7fdeeffe0400) [pid = 3136] [serial = 14] [outer = (nil)]
[task 2018-12-21T15:55:07.906Z] 15:55:07     INFO - GECKO(3136) | ++DOMWINDOW == 15 (0x7fdeeffe3400) [pid = 3136] [serial = 15] [outer = 0x7fdeeffe0400]
[task 2018-12-21T15:55:07.926Z] 15:55:07     INFO - GECKO(3136) | ++DOMWINDOW == 16 (0x7fdef0904400) [pid = 3136] [serial = 16] [outer = 0x7fdeeffe0400]
[task 2018-12-21T15:55:08.187Z] 15:55:08     INFO - GECKO(3136) | [Parent 3136, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 318
[task 2018-12-21T15:55:08.236Z] 15:55:08     INFO - GECKO(3136) | ++DOCSHELL 0x7fdef5153000 == 7 [pid = 3136] [id = {77b0eb40-cb62-43d5-8558-1f298dc0ea4d}]
[task 2018-12-21T15:55:08.243Z] 15:55:08     INFO - GECKO(3136) | ++DOMWINDOW == 17 (0x7fdef0e29800) [pid = 3136] [serial = 17] [outer = (nil)]
[task 2018-12-21T15:55:08.280Z] 15:55:08     INFO - GECKO(3136) | ++DOMWINDOW == 18 (0x7fdef0e2ac00) [pid = 3136] [serial = 18] [outer = 0x7fdef0e29800]
[task 2018-12-21T15:55:08.282Z] 15:55:08     INFO - GECKO(3136) | ++DOMWINDOW == 19 (0x7fdef090b000) [pid = 3136] [serial = 19] [outer = 0x7fdef0e29800]
[task 2018-12-21T15:55:08.693Z] 15:55:08     INFO - GECKO(3136) | --DOCSHELL 0x7f633863f800 == 3 [pid = 3217] [id = {54054054-c480-42c5-b728-53af3f24b901}]
[task 2018-12-21T15:55:12.745Z] 15:55:12     INFO - GECKO(3136) | --DOMWINDOW == 11 (0x7f63394f4000) [pid = 3217] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:12.746Z] 15:55:12     INFO - GECKO(3136) | --DOMWINDOW == 10 (0x7f63394f7800) [pid = 3217] [serial = 8] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:12.747Z] 15:55:12     INFO - GECKO(3136) | --DOMWINDOW == 9 (0x7f63394f6400) [pid = 3217] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:12.748Z] 15:55:12     INFO - GECKO(3136) | --DOMWINDOW == 8 (0x7f6338685800) [pid = 3217] [serial = 5] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:13.712Z] 15:55:13     INFO - GECKO(3136) | --DOMWINDOW == 7 (0x7fcece55cc00) [pid = 3236] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:13.713Z] 15:55:13     INFO - GECKO(3136) | --DOMWINDOW == 6 (0x7fcecd518c00) [pid = 3236] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:15.678Z] 15:55:15     INFO - GECKO(3136) | --DOMWINDOW == 7 (0x7f6338682c00) [pid = 3217] [serial = 4] [outer = (nil)] [url = moz-extension://884320e8-4bdb-4fef-a638-b775725eef0c/_generated_background_page.html]
[task 2018-12-21T15:55:18.017Z] 15:55:18     INFO - GECKO(3136) | --DOMWINDOW == 6 (0x7f63380c8c00) [pid = 3217] [serial = 12] [outer = (nil)] [url = moz-extension://884320e8-4bdb-4fef-a638-b775725eef0c/_generated_background_page.html]
[task 2018-12-21T15:55:18.081Z] 15:55:18     INFO - GECKO(3136) | --DOMWINDOW == 5 (0x7fcecd6c9000) [pid = 3236] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2018-12-21T15:55:18.082Z] 15:55:18     INFO - GECKO(3136) | --DOMWINDOW == 4 (0x7fcecdabe400) [pid = 3236] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2018-12-21T16:00:05.457Z] 16:00:05     INFO - TEST-INFO | started process screentopng
[task 2018-12-21T16:00:05.748Z] 16:00:05     INFO - TEST-INFO | screentopng: exit 0
[task 2018-12-21T16:00:05.750Z] 16:00:05     INFO - Buffered messages logged at 15:55:07
[task 2018-12-21T16:00:05.751Z] 16:00:05     INFO - AddTask.js | Entering test test_setup_keep_uuid_on_uninstall
[task 2018-12-21T16:00:05.752Z] 16:00:05     INFO - AddTask.js | Leaving test test_setup_keep_uuid_on_uninstall
[task 2018-12-21T16:00:05.753Z] 16:00:05     INFO - AddTask.js | Entering test test_uninstall_with_webapi_storages
[task 2018-12-21T16:00:05.754Z] 16:00:05     INFO - Extension loaded
[task 2018-12-21T16:00:05.755Z] 16:00:05     INFO - Extension loaded
[task 2018-12-21T16:00:05.756Z] 16:00:05     INFO - Buffered messages logged at 15:55:08
[task 2018-12-21T16:00:05.758Z] 16:00:05     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html | localStorage data is still present 
[task 2018-12-21T16:00:05.759Z] 16:00:05     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html | indexedDB data is still present 
[task 2018-12-21T16:00:05.761Z] 16:00:05     INFO - Extension loaded
[task 2018-12-21T16:00:05.763Z] 16:00:05     INFO - Buffered messages finished
[task 2018-12-21T16:00:05.764Z] 16:00:05     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html | Test timed out. 
[task 2018-12-21T16:00:05.764Z] 16:00:05     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:275:7
[task 2018-12-21T16:00:05.765Z] 16:00:05     INFO -     reportError@SimpleTest/TestRunner.js:121:7
[task 2018-12-21T16:00:05.765Z] 16:00:05     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2018-12-21T16:00:05.765Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.765Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.765Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:9
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     RunSet.runtests@SimpleTest/setup.js:201:3
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     RunSet.runall@SimpleTest/setup.js:180:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     hookupTests@SimpleTest/setup.js:273:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2018-12-21T16:00:05.766Z] 16:00:05     INFO -     hookup@SimpleTest/setup.js:253:5
[task 2018-12-21T16:00:05.767Z] 16:00:05     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2018-12-21T16:00:06.466Z] 16:00:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-12-21T16:00:06.467Z] 16:00:06     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_storage_cleanup.html | Extension left running at test shutdown 
[task 2018-12-21T16:00:06.467Z] 16:00:06     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:275:7
[task 2018-12-21T16:00:06.468Z] 16:00:06     INFO -     ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:109:7
[task 2018-12-21T16:00:06.468Z] 16:00:06     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1215:19
[task 2018-12-21T16:00:06.469Z] 16:00:06     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1228:5
[task 2018-12-21T16:00:06.469Z] 16:00:06     INFO -     killTest@SimpleTest/TestRunner.js:130:7
[task 2018-12-21T16:00:06.470Z] 16:00:06     INFO -     delayedKillTest@SimpleTest/TestRunner.js:157:47
[task 2018-12-21T16:00:06.471Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:157:7
[task 2018-12-21T16:00:06.471Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.472Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.472Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.473Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.473Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.474Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.475Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.476Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.476Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.477Z] 16:00:06     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
[task 2018-12-21T16:00:06.477Z] 16:00:06     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:9
[task 2018-12-21T16:00:06.478Z] 16:00:06     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
[task 2018-12-21T16:00:06.478Z] 16:00:06     INFO -     RunSet.runtests@SimpleTest/setup.js:201:3
[task 2018-12-21T16:00:06.479Z] 16:00:06     INFO -     RunSet.runall@SimpleTest/setup.js:180:5
[task 2018-12-21T16:00:06.480Z] 16:00:06     INFO -     hookupTests@SimpleTest/setup.js:273:5
[task 2018-12-21T16:00:06.480Z] 16:00:06     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
[task 2018-12-21T16:00:06.480Z] 16:00:06     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
[task 2018-12-21T16:00:06.481Z] 16:00:06     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
[task 2018-12-21T16:00:06.481Z] 16:00:06     INFO -     hookup@SimpleTest/setup.js:253:5
[task 2018-12-21T16:00:06.481Z] 16:00:06     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2018-12-21T16:00:35.461Z] 16:00:35     INFO - Not taking screenshot here: see the one that was previously logged

Comment 1

[Intermittent Failures Robot]

20 failures in 416 pushes (0.048 failures/push) were associated with this bug yesterday.

Repository breakdown:
* mozilla-central: 9
* mozilla-inbound: 8
* autoland: 3

Platform breakdown:
* linux32-nightly: 1
* windows7-32: 3
* linux64-qr: 3
* linux32: 6
* linux64: 6
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1515967&startday=2018-12-21&endday=2018-12-21&tree=all

Comment 2

[Andrei Ciure[:aciure]]

Retriggered:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&searchStr=5f9901d64ac4131f435f7aee39a791361f0657b9&tochange=f711b70e09eeca944f980937988bea94c66dcdb0&fromchange=7bff7a09483d3390388033324f69ebe4b7248a85&group_state=expanded&selectedJob=218545942

Comment 3

[Intermittent Failures Robot]

20 failures in 214 pushes (0.093 failures/push) were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 6
* autoland: 7
* mozilla-central: 7

Platform breakdown:
* linux64: 11
* linux32: 4
* windows10-64: 3
* linux64-qr: 1
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1515967&startday=2018-12-22&endday=2018-12-22&tree=all

Comment 4

[Intermittent Failures Robot]

53 failures in 2648 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #27 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* mozilla-central: 20
* mozilla-inbound: 19
* autoland: 14

Platform breakdown:
* windows10-64: 6
* windows10-64-qr: 1
* linux32: 12
* linux64-qr: 5
* linux64: 23
* linux32-nightly: 1
* windows7-32: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1515967&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 5

[Cosmin Sabou [:CosminS]]

This started failing from this push https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&searchStr=5f9901d64ac4131f435f7aee39a791361f0657b9&tochange=f711b70e09eeca944f980937988bea94c66dcdb0&group_state=expanded&fromchange=f256f0e01e82239fbdc7ec86e32a49a2ccc5b4d7&selectedJob=219280541

with these modifications: https://hg.mozilla.org/integration/mozilla-inbound/rev/0f7da6819c47553e217338f1b7967a60b976b873

It looks that the failures stopped on the 25th: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-11-30&endday=2018-12-30&tree=trunk&bug=1515967

Comment 6

[Andrew Swan [:aswan]]

Looks like they stopped on the 25th due to bug 1516241.

Comment 7

[Intermittent Failures Robot]

13 failures in 1008 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 10
* mozilla-central: 3

Platform breakdown:
* linux64: 8
* linux32: 3
* windows10-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1515967&startday=2018-12-24&endday=2018-12-30&tree=all