1473447 - Intermittent reftest-sanity/font-default.html | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

(Testing :: Reftest, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ccoroiu [at] mozilla.com

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

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

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/R3qBKD9DQEmBQDV5WES3pQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2018-07-03T17:05:07.424Z] 17:05:07     INFO - REFTEST TEST-START | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html
[task 2018-07-03T17:05:07.431Z] 17:05:07     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html | 0 / 1 (0%)
[task 2018-07-03T17:05:07.696Z] 17:05:07     INFO - REFTEST INFO | drawWindow flags = DRAWWINDOW_DRAW_CARET | DRAWWINDOW_DRAW_VIEW | DRAWWINDOW_USE_WIDGET_LAYERS; window size = 800,1000; test browser size = 800,1000
[task 2018-07-03T17:05:07.899Z] 17:05:07     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html | 0 / 1 (0%)
[task 2018-07-03T17:05:08.074Z] 17:05:08     INFO - REFTEST TEST-PASS | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html | image comparison, max difference: 0, number of differing pixels: 0
[task 2018-07-03T17:05:08.075Z] 17:05:08     INFO - REFTEST TEST-END | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html
[task 2018-07-03T17:05:08.107Z] 17:05:08     INFO - REFTEST INFO | Slowest test took 453ms (file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html)
[task 2018-07-03T17:05:08.109Z] 17:05:08     INFO - REFTEST INFO | Total canvas count = 1
[task 2018-07-03T17:05:08.394Z] 17:05:08     INFO - JavaScript error: chrome://reftest/content/reftest.jsm, line 1536: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIPropertyBag2.getPropertyAsAString]
[task 2018-07-03T17:05:08.397Z] 17:05:08     INFO - ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:08.596Z] 17:05:08     INFO - JavaScript error: chrome://reftest/content/reftest.jsm, line 1536: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIPropertyBag2.getPropertyAsAString]
[task 2018-07-03T17:05:08.935Z] 17:05:08     INFO - 1530637508925	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-07-03T17:05:08.936Z] 17:05:08     INFO - 1530637508926	Marionette	INFO	Stopped listening on port 2828
[task 2018-07-03T17:05:08.936Z] 17:05:08     INFO - 1530637508926	Marionette	DEBUG	Remote service is inactive
[task 2018-07-03T17:05:09.685Z] 17:05:09     INFO - REFTEST INFO | Process mode: e10s
[task 2018-07-03T17:05:09.686Z] 17:05:09  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-07-03T17:05:09.687Z] 17:05:09     INFO - REFTEST INFO | Running tests in file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-break/reftest.list
[task 2018-07-03T17:05:09.704Z] 17:05:09     INFO - REFTEST INFO | INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2018-07-03T17:05:09.720Z] 17:05:09     INFO - REFTEST INFO | INFO | runtests.py | ASan running in default memory configuration
[task 2018-07-03T17:05:09.722Z] 17:05:09     INFO - REFTEST INFO | Running with e10s: True
[task 2018-07-03T17:05:09.722Z] 17:05:09     INFO - REFTEST INFO | Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -profile /tmp/tmpo9DZU6.mozrunner
[task 2018-07-03T17:05:11.404Z] 17:05:11     INFO - 1530637511394	Marionette	DEBUG	Received observer notification profile-after-change
[task 2018-07-03T17:05:11.493Z] 17:05:11     INFO - ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2018-07-03T17:05:11.554Z] 17:05:11     INFO - 1530637511552	Marionette	DEBUG	Received observer notification command-line-startup
[task 2018-07-03T17:05:11.555Z] 17:05:11     INFO - 1530637511552	Marionette	DEBUG	Received observer notification nsPref:changed
[task 2018-07-03T17:05:11.557Z] 17:05:11     INFO - 1530637511552	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2018-07-03T17:05:14.935Z] 17:05:14     INFO - 1530637514931	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
[task 2018-07-03T17:05:14.937Z] 17:05:14     INFO - 1530637514931	Marionette	DEBUG	Waiting for delayed startup...
[task 2018-07-03T17:05:16.382Z] 17:05:16     INFO - 1530637516379	Marionette	INFO	Listening on port 2828
[task 2018-07-03T17:05:16.387Z] 17:05:16     INFO - 1530637516381	Marionette	DEBUG	Remote service is active
[task 2018-07-03T17:05:16.492Z] 17:05:16     INFO - 1530637516489	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:56280
[task 2018-07-03T17:05:16.508Z] 17:05:16     INFO - 1530637516504	Marionette	DEBUG	Closed connection 0
[task 2018-07-03T17:05:16.524Z] 17:05:16     INFO - 1530637516512	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:56282
[task 2018-07-03T17:05:16.526Z] 17:05:16     INFO - 1530637516522	Marionette	TRACE	1 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-07-03T17:05:16.912Z] 17:05:16     INFO - 1530637516909	Marionette	DEBUG	[2147483649] Frame script loaded
[task 2018-07-03T17:05:16.934Z] 17:05:16     INFO - 1530637516930	Marionette	DEBUG	[2147483649] Frame script registered
[task 2018-07-03T17:05:16.982Z] 17:05:16     INFO - 1530637516979	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"ef51c875-990d-47ce-9843-0fedba5fc0e5","capabilities":{"browserName":"firefox","browserVersion":"62.0" ... ssID":7454,"moz:profile":"/tmp/tmpo9DZU6.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-07-03T17:05:17.018Z] 17:05:17     INFO - 1530637517009	Marionette	TRACE	1 -> [0,2,"Addon:Install",{"path":"/builds/worker/workspace/build/tests/reftest/reftest","temporary":true}]
[task 2018-07-03T17:05:17.318Z] 17:05:17     INFO - 1530637517311	Marionette	TRACE	1 <- [1,2,null,{"value":"[e-mail]"}]
[task 2018-07-03T17:05:17.920Z] 17:05:17     INFO - 1530637517915	Marionette	TRACE	1 -> [0,3,"WebDriver:DeleteSession",{}]
[task 2018-07-03T17:05:17.923Z] 17:05:17     INFO - 1530637517919	Marionette	TRACE	1 <- [1,3,null,{"value":null}]
[task 2018-07-03T17:05:17.960Z] 17:05:17     INFO - 1530637517954	Marionette	DEBUG	Closed connection 1
[task 2018-07-03T17:05:19.960Z] 17:05:19     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:19.962Z] 17:05:19     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:24.304Z] 17:05:24     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:24.306Z] 17:05:24     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:28.639Z] 17:05:28     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:28.642Z] 17:05:28     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:30.640Z] 17:05:30     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:30.642Z] 17:05:30     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:30.644Z] 17:05:30     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:34.953Z] 17:05:34     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:34.953Z] 17:05:34     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:34.956Z] 17:05:34     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x550027,name=PNecko::Msg_RemoveRequestContext) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:36.954Z] 17:05:36     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:05:36.956Z] 17:05:36     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:01.249Z] 17:06:01     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FC,name=PContent::Msg_UpdateChildScalars) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:01.251Z] 17:06:01     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:15.458Z] 17:06:15     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:15.460Z] 17:06:15     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:26.746Z] 17:06:26     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D0108,name=PContent::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:26.746Z] 17:06:26     INFO - JavaScript error: resource://gre/modules/GCTelemetry.jsm, line 231: NS_ERROR_UNEXPECTED:
[task 2018-07-03T17:06:26.746Z] 17:06:26     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00B1,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:28.698Z] 17:06:28     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:28.700Z] 17:06:28     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:06:28.701Z] 17:06:28     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:10:19.219Z] 17:10:19     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D0108,name=PContent::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:10:19.219Z] 17:10:19     INFO - JavaScript error: resource://gre/modules/GCTelemetry.jsm, line 231: NS_ERROR_UNEXPECTED:
[task 2018-07-03T17:10:19.219Z] 17:10:19     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00B1,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:10:21.136Z] 17:10:21     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:10:21.138Z] 17:10:21     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:10:21.140Z] 17:10:21     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:11:19.270Z] 17:11:19     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D0108,name=PContent::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:11:19.270Z] 17:11:19     INFO - JavaScript error: resource://gre/modules/GCTelemetry.jsm, line 231: NS_ERROR_UNEXPECTED:
[task 2018-07-03T17:11:19.270Z] 17:11:19     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00B1,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:11:21.210Z] 17:11:21     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FA,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:11:21.213Z] 17:11:21     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FB,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:11:21.215Z] 17:11:21     INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2018-07-03T17:17:31.224Z] 17:17:31    ERROR - REFTEST ERROR | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html | application timed out after 370 seconds with no output
[task 2018-07-03T17:17:31.227Z] 17:17:31    ERROR - REFTEST ERROR | Force-terminating active process(es).
[task 2018-07-03T17:17:31.229Z] 17:17:31     INFO - REFTEST TEST-INFO | started process screentopng
[task 2018-07-03T17:17:31.905Z] 17:17:31     INFO - REFTEST TEST-INFO | screentopng: exit 0
[task 2018-07-03T17:17:31.907Z] 17:17:31     INFO - REFTEST INFO | Can't trigger Breakpad, just killing process
[task 2018-07-03T17:17:32.026Z] 17:17:32    ERROR - TEST-UNEXPECTED-FAIL | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/reftest-sanity/font-default.html | application terminated with exit code -15
[task 2018-07-03T17:17:32.034Z] 17:17:32     INFO - REFTEST INFO | Process mode: e10s
[task 2018-07-03T17:17:32.034Z] 17:17:32  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-07-03T17:17:32.035Z] 17:17:32     INFO - REFTEST INFO | Running tests in file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/xul/reftest.list
[task 2018-07-03T17:17:32.056Z] 17:17:32     INFO - REFTEST INFO | INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2018-07-03T17:17:32.066Z] 17:17:32     INFO - REFTEST INFO | INFO | runtests.py | ASan running in default memory configuration
[task 2018-07-03T17:17:32.066Z] 17:17:32     INFO - REFTEST INFO | Running with e10s: True

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1
* mozilla-beta: 1

Platform breakdown:
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473447&startday=2018-07-02&endday=2018-07-08&tree=trunk

Comment 2

[Intermittent Failures Robot]

1 failures in 623 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473447&startday=2018-07-09&endday=2018-07-15&tree=trunk

Comment 3

[Intermittent Failures Robot]

1 failures in 760 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1473447&startday=2018-07-23&endday=2018-07-29&tree=trunk

Comment 4

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup