1628661 - Intermittent Fission high occurrence dom/tests/mochitest/whatwg/test_postMessage_onOther.html | Test timed out.

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Treeherder Bug Filer]

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

---

[task 2020-04-09T10:53:11.591Z] 10:53:11     INFO - TEST-START | dom/tests/mochitest/whatwg/test_postMessage_onOther.html
[task 2020-04-09T10:53:11.711Z] 10:53:11     INFO - GECKO(4053) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-04-09T10:53:11.751Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.751Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.752Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.754Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.755Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.755Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.757Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.758Z] 10:53:11     INFO - GECKO(4053) | [GPU 4088, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 434
[task 2020-04-09T10:53:11.977Z] 10:53:11     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/checkouts/gecko/netwerk/base/nsNetUtil.cpp, line 2307
[task 2020-04-09T10:53:11.977Z] 10:53:11     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 398
[task 2020-04-09T10:53:11.978Z] 10:53:11     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 423
[task 2020-04-09T10:53:11.978Z] 10:53:11     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/checkouts/gecko/netwerk/base/nsNetUtil.cpp, line 2307
[task 2020-04-09T10:53:11.978Z] 10:53:11     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 398
[task 2020-04-09T10:53:11.978Z] 10:53:11     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 423
[task 2020-04-09T10:53:12.019Z] 10:53:12     INFO - GECKO(4053) | [Child 4574, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3352
[task 2020-04-09T10:53:12.124Z] 10:53:12     INFO - GECKO(4053) | nsStringStats
[task 2020-04-09T10:53:12.124Z] 10:53:12     INFO - GECKO(4053) |  => mAllocCount:           8662
[task 2020-04-09T10:53:12.124Z] 10:53:12     INFO - GECKO(4053) |  => mReallocCount:            0
[task 2020-04-09T10:53:12.125Z] 10:53:12     INFO - GECKO(4053) |  => mFreeCount:            8662
[task 2020-04-09T10:53:12.125Z] 10:53:12     INFO - GECKO(4053) |  => mShareCount:           4830
[task 2020-04-09T10:53:12.125Z] 10:53:12     INFO - GECKO(4053) |  => mAdoptCount:            231
[task 2020-04-09T10:53:12.125Z] 10:53:12     INFO - GECKO(4053) |  => mAdoptFreeCount:        241
[task 2020-04-09T10:53:12.125Z] 10:53:12     INFO - GECKO(4053) |  => Process ID: 4574, Thread ID: 140681772128128
[task 2020-04-09T10:53:12.180Z] 10:53:12     INFO - GECKO(4053) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpVZMcwa.mozrunner/runtests_leaks_tab_pid4601.log
[task 2020-04-09T10:53:12.207Z] 10:53:12     INFO - GECKO(4053) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpVZMcwa.mozrunner/runtests_leaks_tab_pid4603.log
[task 2020-04-09T10:53:12.308Z] 10:53:12     INFO - GECKO(4053) | [Child 4419, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/checkouts/gecko/netwerk/base/nsLoadGroup.cpp, line 591
[task 2020-04-09T10:53:12.310Z] 10:53:12     INFO - GECKO(4053) | [Child 4419, Main Thread] WARNING: NS_ENSURE_TRUE(request) failed: file /builds/worker/checkouts/gecko/netwerk/base/nsLoadGroup.cpp, line 591
[task 2020-04-09T10:53:12.495Z] 10:53:12     INFO - GECKO(4053) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-04-09T10:53:12.640Z] 10:53:12     INFO - GECKO(4053) | [Child 4603, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp, line 1678
[task 2020-04-09T10:53:12.676Z] 10:53:12     INFO - GECKO(4053) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-04-09T10:53:12.696Z] 10:53:12     INFO - GECKO(4053) | [Child 4603, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/base/nsPresContext.cpp, line 844
[task 2020-04-09T10:53:12.859Z] 10:53:12     INFO - GECKO(4053) | [Child 4601, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp, line 1678
[task 2020-04-09T10:53:12.894Z] 10:53:12     INFO - GECKO(4053) | [Child 4601, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/base/nsPresContext.cpp, line 844
[task 2020-04-09T10:53:13.069Z] 10:53:13     INFO - GECKO(4053) | JavaScript error: http://example.com/tests/dom/tests/mochitest/whatwg/postMessage_onOther.html, line 88: SecurityError: Permission denied to access property "testSiblingPostMessage" on cross-origin object
[task 2020-04-09T10:58:28.009Z] 10:58:28     INFO - TEST-INFO | started process screentopng
[task 2020-04-09T10:58:28.158Z] 10:58:28     INFO - TEST-INFO | screentopng: exit 0
[task 2020-04-09T10:58:28.162Z] 10:58:28     INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/whatwg/test_postMessage_onOther.html | Test timed out. 
[task 2020-04-09T10:58:28.162Z] 10:58:28     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
[task 2020-04-09T10:58:28.162Z] 10:58:28     INFO -     reportError@SimpleTest/TestRunner.js:128:22
[task 2020-04-09T10:58:28.162Z] 10:58:28     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:18
[task 2020-04-09T10:58:28.163Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.163Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.163Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.163Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.163Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.163Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.164Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.164Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.164Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.164Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.164Z] 10:58:28     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-04-09T10:58:28.164Z] 10:58:28     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:420:16
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:407:48
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO -     RunSet.runtests@SimpleTest/setup.js:218:14
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO -     RunSet.runall@SimpleTest/setup.js:197:12
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO -     hookupTests@SimpleTest/setup.js:294:12
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:13
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:28
[task 2020-04-09T10:58:28.165Z] 10:58:28     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
[task 2020-04-09T10:58:28.166Z] 10:58:28     INFO -     hookup@SimpleTest/setup.js:270:20
[task 2020-04-09T10:58:28.166Z] 10:58:28     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=%2Ftmp&cleanupCrashes=true:11:1
[task 2020-04-09T10:58:29.017Z] 10:58:29     INFO - GECKO(4053) | MEMORY STAT | vsize 2537MB | residentFast 140MB | heapAllocated 11MB
[task 2020-04-09T10:58:29.033Z] 10:58:29     INFO - TEST-OK | dom/tests/mochitest/whatwg/test_postMessage_onOther.html | took 317439ms

Comment 1

[Cristina Coroiu [:ccoroiu]]

Started retriggers on this range:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Linux%2C18.04%2Cx64%2CQuantumRender%2Cdebug%2CMochitests%2Cwith%2Cfission%2Cenabled%2Ctest-linux1804-64-qr%2Fdebug-mochitest-plain-fis-e10s-8%2CM-fis%288%29&tochange=b03fcb814970923bb55f11e69440519c3e020004&fromchange=86458febcf2d1429d32e1c18d238b3232c7d4ad9&selectedJob=296904655

Kris, could be from your push https://hg.mozilla.org/integration/autoland/rev/001575dc6d78bf77bda6bd4949c887ba499e4fa7?

Comment 2

[Intermittent Failures Robot]

44 failures in 1016 pushes (0.043 failures/push) were associated with this bug yesterday.

Repository breakdown:

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

Platform breakdown:

• linux1804-64-qr: 39
• windows10-64: 2
• linux1804-64: 2
• windows10-64-qr: 1

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

Comment 3

[Intermittent Failures Robot]

24 failures in 571 pushes (0.042 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 9
• mozilla-central: 15

Platform breakdown:

• linux1804-64-qr: 12
• linux1804-64: 6
• windows10-64-qr: 4
• windows10-64: 2

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

Comment 4

[Andreea Pavel [:apavel]]

(In reply to Cristina Coroiu [:ccoroiu] from comment #1)

Started retriggers on this range:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Linux%2C18.04%2Cx64%2CQuantumRender%2Cdebug%2CMochitests%2Cwith%2Cfission%2Cenabled%2Ctest-linux1804-64-qr%2Fdebug-mochitest-plain-fis-e10s-8%2CM-fis%288%29&tochange=b03fcb814970923bb55f11e69440519c3e020004&fromchange=86458febcf2d1429d32e1c18d238b3232c7d4ad9&selectedJob=296904655

Kris, could be from your push https://hg.mozilla.org/integration/autoland/rev/001575dc6d78bf77bda6bd4949c887ba499e4fa7?

Try push seems to confirm that theory: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=abe9c234cd10884bb76be84d854dd62b1d6ce7fb

Comment 5

[Intermittent Failures Robot]

86 failures in 4823 pushes (0.018 failures/push) were associated with this bug in the last 7 days.

This is the #9 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 52
• mozilla-central: 32
• try: 2

Platform breakdown:

• linux1804-64-qr: 60
• windows10-64: 6
• linux1804-64: 13
• windows10-64-qr: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1628661&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 6

[Cristina Coroiu [:ccoroiu]]

The culprit has been backed out here: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=f8e4bf7b35ad28492ee8300b78bb376b9a90b0c2

https://bugzilla.mozilla.org/show_bug.cgi?id=1582318#c47

Comment 7

[Intermittent Failures Robot]

2 failures in 4528 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2

Platform breakdown:

• linux1804-64: 2

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