1609806 - Intermittent docshell/test/mochitest/test_bug529119-1.html | Test timed out.

Status: RESOLVED INCOMPLETE

(Core :: DOM: Navigation, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=285255393&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/KIB8FbbLTXmu9h1pc03rDQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-01-16T21:27:21.622Z] 21:27:21 INFO - TEST-START | docshell/test/mochitest/test_bug529119-1.html
[task 2020-01-16T21:27:21.706Z] 21:27:21 INFO - GECKO(1116) | [Parent 1116, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-16T21:27:21.727Z] 21:27:21 INFO - GECKO(1116) | [Child 1297, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63
[task 2020-01-16T21:27:22.360Z] 21:27:22 INFO - GECKO(1116) | [Parent 1116, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-16T21:27:22.360Z] 21:27:22 INFO - GECKO(1116) | [Child 1297, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63
[task 2020-01-16T21:27:22.761Z] 21:27:22 INFO - GECKO(1116) | [Child 1297, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63
[task 2020-01-16T21:27:22.763Z] 21:27:22 INFO - GECKO(1116) | [Child 1297, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63
[task 2020-01-16T21:27:22.764Z] 21:27:22 INFO - GECKO(1116) | [Child 1297, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/workspace/build/src/netwerk/base/nsLoadGroup.cpp, line 584
[task 2020-01-16T21:27:22.893Z] 21:27:22 INFO - GECKO(1116) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpfAldEq.mozrunner/runtests_leaks_tab_pid1396.log
[task 2020-01-16T21:27:22.948Z] 21:27:22 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 721
[task 2020-01-16T21:27:22.949Z] 21:27:22 INFO - GECKO(1116) | [Parent 1116, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-16T21:27:23.105Z] 21:27:23 INFO - GECKO(1116) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-01-16T21:27:23.327Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 1822
[task 2020-01-16T21:27:23.408Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 848
[task 2020-01-16T21:27:23.639Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63
[task 2020-01-16T21:27:23.687Z] 21:27:23 INFO - GECKO(1116) | JavaScript error: , line 0: NS_ERROR_NOT_AVAILABLE
[task 2020-01-16T21:27:23.688Z] 21:27:23 INFO - GECKO(1116) | JavaScript error: , line 0: NS_ERROR_NOT_AVAILABLE
[task 2020-01-16T21:27:23.764Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: '!mCanSend || !mManager || !mManager->CanSend()', file /builds/worker/workspace/build/src/dom/ipc/JSWindowActorChild.cpp, line 78
[task 2020-01-16T21:27:23.784Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: '!mCanSend || !mManager || !mManager->CanSend()', file /builds/worker/workspace/build/src/dom/ipc/JSWindowActorChild.cpp, line 78
[task 2020-01-16T21:27:23.886Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: '!tsi', file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 1577
[task 2020-01-16T21:27:23.967Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: '!aWin', file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 1398
[task 2020-01-16T21:27:23.968Z] 21:27:23 INFO - GECKO(1116) | [Child 1396, Main Thread] WARNING: '!aWin', file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 1398
[task 2020-01-16T21:32:22.312Z] 21:32:22 INFO - TEST-INFO | started process screentopng
[task 2020-01-16T21:32:22.568Z] 21:32:22 INFO - TEST-INFO | screentopng: exit 0
[task 2020-01-16T21:32:22.569Z] 21:32:22 INFO - Buffered messages logged at 21:27:22
[task 2020-01-16T21:32:22.570Z] 21:32:22 INFO - TEST-PASS | docshell/test/mochitest/test_bug529119-1.html | A valid string reason is expected
[task 2020-01-16T21:32:22.570Z] 21:32:22 INFO - TEST-PASS | docshell/test/mochitest/test_bug529119-1.html | Reason cannot be empty
[task 2020-01-16T21:32:22.571Z] 21:32:22 INFO - TEST-FAIL | docshell/test/mochitest/test_bug529119-1.html | The author of the test has indicated that flaky timeouts are expected. Reason: untriaged
[task 2020-01-16T21:32:22.571Z] 21:32:22 INFO - Buffered messages finished
[task 2020-01-16T21:32:22.572Z] 21:32:22 INFO - TEST-UNEXPECTED-FAIL | docshell/test/mochitest/test_bug529119-1.html | Test timed out.
[task 2020-01-16T21:32:22.572Z] 21:32:22 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2020-01-16T21:32:22.573Z] 21:32:22 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2020-01-16T21:32:22.573Z] 21:32:22 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2020-01-16T21:32:22.573Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.574Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.575Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.575Z] 21:32:22 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2020-01-16T21:32:22.575Z] 21:32:22 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:388:20
[task 2020-01-16T21:32:22.575Z] 21:32:22 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:375:50
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:13
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:28
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - hookup@SimpleTest/setup.js:253:20
[task 2020-01-16T21:32:22.577Z] 21:32:22 INFO - EventHandlerNonNull@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2020-01-16T21:32:23.320Z] 21:32:23 INFO - GECKO(1116) | MEMORY STAT | vsize 2530MB | residentFast 145MB | heapAllocated 11MB
[task 2020-01-16T21:32:25.328Z] 21:32:25 INFO - TEST-OK | docshell/test/mochitest/test_bug529119-1.html | took 303712ms
[task 2020-01-16T21:32:28.335Z] 21:32:28 INFO - Error: Unable to restore focus, expect failures and timeouts.
[task 2020-01-16T21:32:28.351Z] 21:32:28 INFO - GECKO(1116) | [Parent 1116, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-16T21:32:28.352Z] 21:32:28 INFO - GECKO(1116) | [Child 1297, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63

Comment 1

[Boris Zbarsky [:bzbarsky]]

I'll take a look, but I won't be able to do that until Monday.

The other failures starred on https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=4153f03aa6ab82f6ab8d430cca47ebe6236fb3ae as being bug 1605807 are not that bug: they're a different failure, at a different point in the test. They may or may not be related to the timeout, but definitely need to be fixed.

Comment 2

[Noemi Erli[:noemi_erli]]

Retrigger and backfill range: https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&searchStr=9934afd631850a127a921afab3dfeb69eaa3548a&fromchange=3ff2a46e08145e5da7b1e40d29671f7ab0f11697&tochange=4153f03aa6ab82f6ab8d430cca47ebe6236fb3ae&selectedJob=285275115

Comment 3

[Boris Zbarsky [:bzbarsky]]

I expect both this and the about:blank error are the result of the patch from bug 1605807. It I have some ideas for how to fix, but again probably not until Monday.

Comment 4

[Edwin Takahashi (:egao | infrequent contributor)]

I have also landed https://phabricator.services.mozilla.com/D59970 which prompted this test to be a near permafail in the first place.

This patch appears to have made its way past autoland, which means by Monday on mozilla-central, mochitests-e10s on linux will be running on the ubuntu1804-test docker image.

Comment 5

[Edwin Takahashi (:egao | infrequent contributor)]

I should clarify what having the test run on ubuntu1804 means; it should lead to much lower, if any, intermittent failure of this particular test.

For the sister test to this docshell/test/mochitest/test_bug529119-2.html :bzbarsky also mentioned rewriting it to be less racy.

Comment 6

[Boris Zbarsky [:bzbarsky]]

I believe that the second patch I just put up in bug 1605807 will address this...

Comment 7

[Intermittent Failures Robot]

19 failures in 3773 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 11
• mozilla-central: 6
• try: 2

Platform breakdown:

• linux64-qr: 8
• windows10-64-qr: 2
• linux1804-64-qr: 7
• windows10-64: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1609806&startday=2020-01-13&endday=2020-01-19&tree=all

Comment 8

[Intermittent Failures Robot]

20 failures in 543 pushes (0.037 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 1
• autoland: 18
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 1
• linux1804-64-qr: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1609806&startday=2020-01-20&endday=2020-01-20&tree=all

Comment 9

[Intermittent Failures Robot]

32 failures in 4004 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #42 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:

• try: 13
• autoland: 18
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 5
• linux1804-64-qr: 24
• windows10-64-qr: 2
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1609806&startday=2020-01-20&endday=2020-01-26&tree=all

Comment 10

[Boris Zbarsky [:bzbarsky]]

All the failures from after bug 1605807 landed are on try; presumably people pushing changesets on top of old trees.

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.