1425394 - Intermittent mochitest-screenshots timed out after 1000 seconds of no output

Status: RESOLVED FIXED

(Testing :: mozscreenshots, defect, P1)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com

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

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

12:03:42     INFO - TEST-START | browser/tools/mozscreenshots/preferences/browser_preferences.js
12:03:42     INFO - GECKO(2390) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:43     INFO - GECKO(2390) | 2017-12-14 12:03:43.370 plugin-container[2392:14485] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9d47, name = 'com.apple.tsm.portname'
12:03:43     INFO - GECKO(2390) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:03:44     INFO - GECKO(2390) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:45     INFO - GECKO(2390) | 2017-12-14 12:03:45.076 plugin-container[2393:14548] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9c57, name = 'com.apple.tsm.portname'
12:03:45     INFO - GECKO(2390) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:03:47     INFO - GECKO(2390) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
12:03:47     INFO - GECKO(2390) | MEMORY STAT | vsize 4286MB | residentFast 415MB | heapAllocated 163MB
12:03:47     INFO - TEST-OK | browser/tools/mozscreenshots/preferences/browser_preferences.js | took 4586ms
12:03:47     INFO - checking window state
12:03:47     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
12:03:48     INFO - GECKO(2390) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:48     INFO - GECKO(2390) | 2017-12-14 12:03:48.652 plugin-container[2397:14603] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9e4b, name = 'com.apple.tsm.portname'
12:03:48     INFO - GECKO(2390) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:03:48     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
12:03:49     INFO - GECKO(2390) | Completed ShutdownLeaks collections in process 2392
12:03:49     INFO - GECKO(2390) | Completed ShutdownLeaks collections in process 2393
12:03:49     INFO - GECKO(2390) | Completed ShutdownLeaks collections in process 2391
12:03:49     INFO - GECKO(2390) | Completed ShutdownLeaks collections in process 2397
12:03:49     INFO - GECKO(2390) | Completed ShutdownLeaks collections in process 2390
12:03:49     INFO - TEST-START | Shutdown
12:03:49     INFO - Browser Chrome Test Summary
12:03:49     INFO - Passed:  2
12:03:49     INFO - Failed:  0
12:03:49     INFO - Todo:    0
12:03:49     INFO - Mode:    e10s
12:03:49     INFO - *** End BrowserChrome Test Results ***
12:03:50     INFO - GECKO(2390) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
12:03:50     INFO - GECKO(2390) | 1513281830212	Marionette	DEBUG	Received observer notification "xpcom-shutdown"
12:03:50     INFO - GECKO(2390) | 1513281830212	Marionette	DEBUG	New connections will no longer be accepted
12:03:50     INFO - TEST-INFO | Main app process: exit 0
12:03:50     INFO - runtests.py | Application ran for: 0:00:10.742801
12:03:50     INFO - zombiecheck | Reading PID log: /var/folders/nr/w4tjyw_974q8yvsdmhf27yw400000w/T/tmpKAECuGpidlog
12:03:50     INFO - ==> process 2390 launched child process 2391
12:03:50     INFO - ==> process 2390 launched child process 2392
12:03:50     INFO - ==> process 2390 launched child process 2393
12:03:50     INFO - ==> process 2390 launched child process 2397
12:03:50     INFO - zombiecheck | Checking for orphan process with PID: 2392
12:03:50     INFO - zombiecheck | Checking for orphan process with PID: 2393
12:03:50     INFO - zombiecheck | Checking for orphan process with PID: 2397
12:03:50     INFO - zombiecheck | Checking for orphan process with PID: 2391
12:03:50     INFO - Stopping web server
12:03:50     INFO - Stopping web socket server
12:03:50     INFO - Stopping ssltunnel
12:03:50  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
12:03:50     INFO - runtests.py | Running tests: end.
12:03:50     INFO - Buffered messages finished
12:03:50     INFO - Running manifest: browser/tools/mozscreenshots/primaryUI/browser.ini
12:03:50     INFO -  pk12util: PKCS12 IMPORT SUCCESSFUL
12:03:50     INFO - MochitestServer : launching [u'/Users/cltbld/tasks/task_1513280858/build/tests/bin/xpcshell', '-g', '/Users/cltbld/tasks/task_1513280858/build/application/Nightly.app/Contents/Resources', '-f', '/Users/cltbld/tasks/task_1513280858/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/var/folders/nr/w4tjyw_974q8yvsdmhf27yw400000w/T/tmpkObXi1.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/Users/cltbld/tasks/task_1513280858/build/tests/mochitest/server.js']
12:03:50     INFO - runtests.py | Server pid: 2405
12:03:50     INFO - runtests.py | Websocket server pid: 2406
12:03:50     INFO - runtests.py | SSL tunnel pid: 2407
12:03:51     INFO - runtests.py | Running with e10s: True
12:03:51     INFO - runtests.py | Running tests: start.
12:03:51     INFO - 
12:03:51     INFO - Application command: /Users/cltbld/tasks/task_1513280858/build/application/Nightly.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/nr/w4tjyw_974q8yvsdmhf27yw400000w/T/tmpkObXi1.mozrunner
12:03:51     INFO - runtests.py | Application pid: 2408
12:03:51     INFO - TEST-INFO | started process GECKO(2408)
12:03:51     INFO - GECKO(2408) | 1513281831812	Marionette	DEBUG	Received observer notification "profile-after-change"
12:03:51     INFO - GECKO(2408) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:51     INFO - GECKO(2408) | 1513281831892	Marionette	DEBUG	Received observer notification "command-line-startup"
12:03:51     INFO - GECKO(2408) | 1513281831892	Marionette	INFO	Enabled via --marionette
12:03:52     INFO - GECKO(2408) | 1513281832885	Marionette	DEBUG	Received observer notification "sessionstore-windows-restored"
12:03:52     INFO - GECKO(2408) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:53     INFO - GECKO(2408) | 2017-12-14 12:03:53.246 plugin-container[2409:14798] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9f3f, name = 'com.apple.tsm.portname'
12:03:53     INFO - GECKO(2408) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:03:53     INFO - GECKO(2408) | 1513281833270	Marionette	DEBUG	New connections are accepted
12:03:53     INFO - GECKO(2408) | 1513281833271	Marionette	INFO	Listening on port 2828
12:03:53     INFO - GECKO(2408) | 1513281833306	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49562
12:03:53     INFO - GECKO(2408) | 1513281833318	Marionette	DEBUG	Closed connection 0
12:03:53     INFO - GECKO(2408) | 1513281833319	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:49563
12:03:53     INFO - GECKO(2408) | 1513281833330	Marionette	TRACE	1 -> [0,1,"newSession",{}]
12:03:53     INFO - GECKO(2408) | 1513281833417	Marionette	DEBUG	Register listener.js for window 2147483649
12:03:53     INFO - GECKO(2408) | 1513281833430	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"68f96dc3-3b0c-0a43-ae6e-eb8d42594fec","capabilities":{"browserName":"firefox","browserVersion":"59.0a ... essID":2408,"moz:profile":"/var/folders/nr/w4tjyw_974q8yvsdmhf27yw400000w/T/tmpkObXi1.mozrunner","moz:webdriverClick":true}}]
12:03:53     INFO - GECKO(2408) | 1513281833446	Marionette	TRACE	1 -> [0,2,"addon:install",{"path":"/var/folders/nr/w4tjyw_974q8yvsdmhf27yw400000w/T/tmpEWwzwm.zip","temporary":false}]
12:03:53     INFO - GECKO(2408) | 1513281833547	Marionette	TRACE	1 <- [1,2,null,{"value":"[e-mail]"}]
12:03:53     INFO - GECKO(2408) | 1513281833600	Marionette	TRACE	1 -> [0,3,"addon:install",{"path":"/var/folders/nr/w4tjyw_974q8yvsdmhf27yw400000w/T/tmpNO1tAf.zip","temporary":false}]
12:03:53     INFO - GECKO(2408) | 1513281833658	Marionette	TRACE	1 <- [1,3,null,{"value":"[e-mail]"}]
12:03:53     INFO - GECKO(2408) | 1513281833661	Marionette	TRACE	1 -> [0,4,"getContext",{}]
12:03:53     INFO - GECKO(2408) | 1513281833662	Marionette	TRACE	1 <- [1,4,null,{"value":"content"}]
12:03:53     INFO - GECKO(2408) | 1513281833666	Marionette	TRACE	1 -> [0,5,"setContext",{"value":"chrome"}]
12:03:53     INFO - GECKO(2408) | 1513281833666	Marionette	TRACE	1 <- [1,5,null,{}]
12:03:53     INFO - GECKO(2408) | 1513281833670	Marionette	TRACE	1 -> [0,6,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[{"testUrl":"about:blank","flavor":"browser-chrome"}],"fi ...  = new CustomEvent('mochitest-load', {'detail': [flavor, url]});\nwin.dispatchEvent(ev);\n","sandbox":"default","line":1734}]
12:03:53     INFO - GECKO(2408) | 1513281833675	Marionette	TRACE	1 <- [1,6,null,{"value":null}]
12:03:53     INFO - GECKO(2408) | 1513281833726	Marionette	TRACE	1 -> [0,7,"setContext",{"value":"content"}]
12:03:53     INFO - GECKO(2408) | 1513281833727	Marionette	TRACE	1 <- [1,7,null,{}]
12:03:53     INFO - GECKO(2408) | 1513281833736	Marionette	TRACE	1 -> [0,8,"deleteSession",{}]
12:03:53     INFO - GECKO(2408) | 1513281833738	Marionette	TRACE	1 <- [1,8,null,{}]
12:03:53     INFO - runtests.py | Waiting for browser...
12:03:53     INFO - GECKO(2408) | 1513281833765	Marionette	DEBUG	Closed connection 1
12:03:54     INFO - *** Start BrowserChrome Test Results ***
12:03:54     INFO - checking window state
12:03:54     INFO - TEST-START | browser/tools/mozscreenshots/primaryUI/browser_primaryUI.js
12:03:54     INFO - GECKO(2408) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:55     INFO - GECKO(2408) | 2017-12-14 12:03:55.134 plugin-container[2410:14881] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9c53, name = 'com.apple.tsm.portname'
12:03:55     INFO - GECKO(2408) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:03:55     INFO - GECKO(2408) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:56     INFO - GECKO(2408) | 2017-12-14 12:03:56.719 plugin-container[2411:14924] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0xa457, name = 'com.apple.tsm.portname'
12:03:56     INFO - GECKO(2408) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:03:56     INFO - GECKO(2408) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
12:03:57     INFO - GECKO(2408) | 2017-12-14 12:03:57.093 plugin-container[2412:14959] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0xa43b, name = 'com.apple.tsm.portname'
12:03:57     INFO - GECKO(2408) | See /usr/include/servers/bootstrap_defs.h for the error codes.
12:04:06     INFO - GECKO(2408) | 1513281845995	addons.xpi	WARN	Attempting to activate an already active default theme
12:04:11     INFO - GECKO(2408) | 2017-12-14 12:04:11.567 firefox[2408:15066] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
12:20:51     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/Users/cltbld/tasks/task_1513280858/build/venv/bin/python', '-u', '/Users/cltbld/tasks/task_1513280858/build/tests/mochitest/runtests.py', '--appname=/Users/cltbld/tasks/task_1513280858/build/application/Nightly.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/deQeAOJXQZyWSt2t51WNtQ/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--quiet', '--log-raw=/Users/cltbld/tasks/task_1513280858/build/blobber_upload_dir/browser-chrome-screenshots_raw.log', '--log-errorsummary=/Users/cltbld/tasks/task_1513280858/build/blobber_upload_dir/browser-chrome-screenshots_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/Users/cltbld/tasks/task_1513280858/build', '--log-raw=-', '--flavor=browser', '--subsuite=screenshots']
12:20:51    ERROR - timed out after 1000 seconds of no output
12:20:51    ERROR - Return code: -15
12:20:51    ERROR - No suite end message was emitted by this harness.
12:20:51     INFO - TinderboxPrint: mochitest-browser-chrome-screenshots<br/>7/0/0
12:20:51    ERROR - # TBPL FAILURE #
12:20:51  WARNING - setting return code to 2
12:20:51    ERROR - The mochitest suite: browser-chrome-screenshots ran with return status: FAILURE
12:20:51     INFO - Running post-action listener: _package_coverage_data
12:20:51     INFO - Running post-action listener: _resource_record_post_action
12:20:51     INFO - [mozharness: 2017-12-14 20:20:51.605985Z] Finished run-tests step (success)

Comment 1

[Phil Ringnalda (:philor)]

And this isn't new, they've just always been misstarred as some other bug when they were just once every other day on mozilla-central.

Comment 2

[Andreea Pavel [:apavel]]

Thanks for the update :philor.

Comment 3

[Matthew N. [:MattN]]

This seems like a harness issue to me but I'm not sure…
> Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)

I'm not sure if the above message is the cause of the timeout or not? ahal, what do you think or who would know?

Comment 5

[Phil Ringnalda (:philor)]

Fun, that line must search out into the tasks/task_nnnnn part of the summary, so it's not suggested.

Comment 7

[Intermittent Failures Robot]

35 failures in 423 pushes (0.083 failures/push) were associated with this bug in the last 7 days. 

This is the #19 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-inbound: 15
* autoland: 13
* mozilla-central: 7

Platform breakdown:
* osx-10-10: 33
* windows7-32: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2017-12-11&endday=2017-12-17&tree=all

Comment 8

[Andrew Halberstadt [:ahal]]

That string definitely isn't printed from anywhere in mozilla-central.

After some googling, it looks like a fairly generic error that can happen intermittently on OSX. Some have suggested it could be a permissions issue, others say it can happen from using too many file descriptors. If this error happens exclusively with the mozscreenshot tests, I'd lean towards it being a test issue (though I wouldn't rule out a harness problem).

Comment 9

[Andrew Halberstadt [:ahal]]

This is 100% speculative, but if I were a betting man, I'd put money on this triggering the error:
https://searchfox.org/mozilla-central/source/browser/tools/mozscreenshots/mozscreenshots/extension/TestRunner.jsm#211

Comment 10

[Intermittent Failures Robot]

28 failures in 108 pushes (0.259 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 16
* autoland: 10
* mozilla-central: 2

Platform breakdown:
* osx-10-10: 16
* linux64: 9
* linux64-jsdcov: 2
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2017-12-20&endday=2017-12-20&tree=all

Comment 11

[Intermittent Failures Robot]

19 failures in 170 pushes (0.112 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 13
* mozilla-inbound: 4
* try: 1
* mozilla-central: 1

Platform breakdown:
* osx-10-10: 19

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2017-12-21&endday=2017-12-21&tree=all

Comment 12

[Intermittent Failures Robot]

68 failures in 590 pushes (0.115 failures/push) were associated with this bug in the last 7 days. 

This is the #12 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:
* autoland: 39
* mozilla-inbound: 24
* mozilla-central: 5

Platform breakdown:
* osx-10-10: 49
* linux64: 14
* linux64-jsdcov: 3
* windows7-32: 1
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2017-12-18&endday=2017-12-24&tree=all

Comment 13

[Eliza Balazs [:ebalazs_]]

There are 54 failures in the last 7 days.
They occur mostly on OS X 10.10 and the rest of them on linux64-jsdcov, Linux x64 and Windows 7.
The affected builds type are asan, debug, opt, pgo.
Here is a recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=153328224&lineNumber=1913
and a relevant part of the log:
03:00:18     INFO - TEST-START | browser/tools/mozscreenshots/primaryUI/browser_primaryUI.js
1903
03:00:18     INFO - GECKO(2563) | /System/Library/LaunchAgents/com.apple.notificationcenterui.plist: Could not find specified service
1904
03:00:18     INFO - GECKO(2563) | No matching processes belonging to you were found
1905
03:00:20     INFO - GECKO(2563) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
1906
03:00:20     INFO - GECKO(2563) | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
1907
03:00:20     INFO - GECKO(2563) | 2017-12-25 03:00:20.795 plugin-container[2570:44840] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0xa243, name = 'com.apple.tsm.portname'
1908
03:00:20     INFO - GECKO(2563) | See /usr/include/servers/bootstrap_defs.h for the error codes.
1909
03:00:21     INFO - GECKO(2563) | 2017-12-25 03:00:21.093 plugin-container[2569:44829] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0xa54b, name = 'com.apple.tsm.portname'
1910
03:00:21     INFO - GECKO(2563) | See /usr/include/servers/bootstrap_defs.h for the error codes.
1911
03:00:30     INFO - GECKO(2563) | 1514199630095	addons.xpi	WARN	Attempting to activate an already active default theme
1912
03:00:35     INFO - GECKO(2563) | 2017-12-25 03:00:35.595 firefox[2563:44640] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
1913
03:17:15     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/Users/cltbld/tasks/task_1514156953/build/venv/bin/python', '-u', '/Users/cltbld/tasks/task_1514156953/build/tests/mochitest/runtests.py', '--appname=/Users/cltbld/tasks/task_1514156953/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/Heeudk-YQGCdJdeIkDB7tg/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--quiet', '--log-raw=/Users/cltbld/tasks/task_1514156953/build/blobber_upload_dir/browser-chrome-screenshots_raw.log', '--log-errorsummary=/Users/cltbld/tasks/task_1514156953/build/blobber_upload_dir/browser-chrome-screenshots_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/Users/cltbld/tasks/task_1514156953/build', '--log-raw=-', '--flavor=browser', '--subsuite=screenshots']
1914
03:17:15    ERROR - timed out after 1000 seconds of no output
1915
03:17:15    ERROR - Return code: -15
1916
03:17:15    ERROR - No suite end message was emitted by this harness.
1917
03:17:15     INFO - TinderboxPrint: mochitest-browser-chrome-screenshots<br/>7/0/0
1918
03:17:15    ERROR - # TBPL FAILURE #
1919
03:17:15  WARNING - setting return code to 2
1920
03:17:15    ERROR - The mochitest suite: browser-chrome-screenshots ran with return status: FAILURE
1921
03:17:15     INFO - Running post-action listener: _package_coverage_data
1922
03:17:15     INFO - Running post-action listener: _resource_record_post_action
1923
03:17:15     INFO - [mozharness: 2017-12-25 11:17:15.668483Z] Finished run-tests step (success)
1924
03:17:15     INFO - Running post-run listener: _resource_record_post_run
1925
03:17:15     INFO - Validating Perfherder data against /Users/cltbld/tasks/task_1514156953/mozharness/external_tools/performance-artifact-schema.json
1926
03:17:15     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 44.571380778588846}, {"name": "io_write_bytes", "value": 851233792}, {"name": "io.read_bytes", "value": 296253952}, {"name": "io_write_time", "value": 4077}, {"name": "io_read_time", "value": 18079}], "extraOptions": ["e10s", "buildbot-unknown"], "name": "mochitest.browser-chrome-screenshots.browser-chrome-screenshots.overall"}, {"subtests": [{"name": "time", "value": 23.013200998306274}, {"name": "cpu_percent", "value": 53.575}], "name": "mochitest.browser-chrome-screenshots.browser-chrome-screenshots.install"}, {"subtests": [{"name": "time", "value": 0.0003809928894042969}], "name": "mochitest.browser-chrome-screenshots.browser-chrome-screenshots.stage-files"}, {"subtests": [{"name": "time", "value": 1622.2110149860382}, {"name": "cpu_percent", "value": 44.43672839506177}], "name": "mochitest.browser-chrome-screenshots.browser-chrome-screenshots.run-tests"}]}
1927
03:17:15     INFO - Total resource usage - Wall time: 1645s; CPU: 44.0%; Read bytes: 296253952; Write bytes: 851233792; Read time: 18079; Write time: 4077
1928
03:17:15     INFO - TinderboxPrint: CPU usage<br/>44.4%
1929
03:17:15     INFO - TinderboxPrint: I/O read bytes / time<br/>296,253,952 / 18,079
1930
03:17:15     INFO - TinderboxPrint: I/O write bytes / time<br/>851,233,792 / 4,077
1931
03:17:15     INFO - TinderboxPrint: CPU idle<br/>3,646.6 (55.4%)
1932
03:17:15     INFO - TinderboxPrint: CPU system<br/>1,504.9 (22.9%)
1933
03:17:15     INFO - TinderboxPrint: CPU user<br/>1,427.8 (21.7%)
1934
03:17:15     INFO - TinderboxPrint: Swap in / out<br/>298,283,008 / 0
1935
03:17:15     INFO - install - Wall time: 23s; CPU: 54.0%; Read bytes: 243599360; Write bytes: 242671616; Read time: 17739; Write time: 503
1936
03:17:15     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
1937
03:17:15     INFO - run-tests - Wall time: 1622s; CPU: 44.0%; Read bytes: 39604736; Write bytes: 585645056; Read time: 280; Write time: 3481
1938
03:17:16     INFO - Running post-run listener: _upload_blobber_files
1939
03:17:16  WARNING - Blob upload gear skipped. Missing cmdline options.
1940
03:17:16     INFO - Running post-run listener: copy_logs_to_upload_dir
1941
03:17:16     INFO - Copying logs to upload dir...
1942
03:17:16     INFO - mkdir: /Users/cltbld/tasks/task_1514156953/build/upload/logs
1943
03:17:16     INFO - Copying logs to upload dir...
1944
03:17:16  WARNING - returning nonzero exit status 2
1945
[taskcluster 2017-12-25T11:17:16.473Z] Exit Code: 2
1946
[taskcluster 2017-12-25T11:17:16.473Z] === Task Finished ===
1947
[taskcluster 2017-12-25T11:17:16.473Z] Task Duration: 29m17.900453872s

Comment 14

[Intermittent Failures Robot]

11 failures in 147 pushes (0.075 failures/push) were associated with this bug in the last 7 days. 

This is the #19 most frequent failure this week.   

Repository breakdown:
* mozilla-central: 6
* autoland: 3
* mozilla-inbound: 2

Platform breakdown:
* osx-10-10: 7
* linux64-jsdcov: 3
* windows7-32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2017-12-25&endday=2017-12-31&tree=all

Comment 15

[Intermittent Failures Robot]

15 failures in 111 pushes (0.135 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 9
* mozilla-inbound: 4
* mozilla-central: 2

Platform breakdown:
* osx-10-10: 15

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-03&endday=2018-01-03&tree=all

Comment 16

[Raul Gurzau (:RaulG)]

As an update, there are 46 failures in the past week for this bug, a spike can be seen on 30th Dec after which it begins to settle down.

The failures occur mostly on OS X 10.10 opt

Recent log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=154375565&lineNumber=1925


06:06:44     INFO - GECKO(1361) | 1515161204182	addons.xpi	WARN	Attempting to activate an already active default theme
06:06:49     INFO - GECKO(1361) | 2018-01-05 06:06:49.682 firefox[1361:16358] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
06:23:29     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/Users/cltbld/tasks/task_1515152901/build/venv/bin/python', '-u', '/Users/cltbld/tasks/task_1515152901/build/tests/mochitest/runtests.py', '--appname=/Users/cltbld/tasks/task_1515152901/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/TvoGcTqrTqK5e12i476zqQ/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--quiet', '--log-raw=/Users/cltbld/tasks/task_1515152901/build/blobber_upload_dir/browser-chrome-screenshots_raw.log', '--log-errorsummary=/Users/cltbld/tasks/task_1515152901/build/blobber_upload_dir/browser-chrome-screenshots_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/Users/cltbld/tasks/task_1515152901/build', '--log-raw=-', '--flavor=browser', '--subsuite=screenshots']
06:23:29    ERROR - timed out after 1000 seconds of no output
06:23:29    ERROR - Return code: -15
06:23:29    ERROR - No suite end message was emitted by this harness.
06:23:29     INFO - TinderboxPrint: mochitest-browser-chrome-screenshots<br/>7/0/0
06:23:29    ERROR - # TBPL FAILURE #
06:23:29  WARNING - setting return code to 2
06:23:29    ERROR - The mochitest suite: browser-chrome-screenshots ran with return status: FAILURE
06:23:29     INFO - Running post-action listener: _package_coverage_data
06:23:29     INFO - Running post-action listener: _resource_record_post_action

Comment 17

[Intermittent Failures Robot]

57 failures in 462 pushes (0.123 failures/push) were associated with this bug in the last 7 days. 

This is the #10 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:
* autoland: 31
* mozilla-inbound: 20
* mozilla-central: 5
* try: 1

Platform breakdown:
* osx-10-10: 54
* linux64-jsdcov: 1
* linux64: 1
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-01&endday=2018-01-07&tree=all

Comment 18

[Intermittent Failures Robot]

30 failures in 152 pushes (0.197 failures/push) were associated with this bug yesterday.    

** This test has failed more than 200 times in the last 30 days. It should be disabled until it can be fixed. ** 

Repository breakdown:
* autoland: 17
* mozilla-inbound: 11
* mozilla-central: 2

Platform breakdown:
* osx-10-10: 28
* windows7-32: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-10&endday=2018-01-10&tree=all

Comment 19

[Joel Maher ( :jmaher ) (UTC -8)]

MattN, should we disable this on OSX or make it tier-3 until we can figure out why this is timing out so frequently?  I suspect this is the same root cause as bug 1391545.

Comment 20

[Intermittent Failures Robot]

18 failures in 149 pushes (0.121 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 11
* autoland: 4
* mozilla-central: 3

Platform breakdown:
* osx-10-10: 16
* linux64-jsdcov: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-11&endday=2018-01-11&tree=all

Comment 21

[Intermittent Failures Robot]

20 failures in 148 pushes (0.135 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 10
* autoland: 10

Platform breakdown:
* osx-10-10: 19
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-12&endday=2018-01-12&tree=all

Comment 22

[Intermittent Failures Robot]

96 failures in 788 pushes (0.122 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: 46
* mozilla-inbound: 43
* mozilla-central: 7

Platform breakdown:
* osx-10-10: 87
* linux64: 5
* linux64-jsdcov: 2
* windows7-32: 1
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-08&endday=2018-01-14&tree=all

Comment 23

[Matthew N. [:MattN]]

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #19)
> MattN, should we disable this on OSX or make it tier-3 until we can figure
> out why this is timing out so frequently?  I suspect this is the same root
> cause as bug 1391545.

I'm not even sure there is really a problem with the test here… If it's just complaining that the test hasn't sent output for 1000 seconds then that's expected without requestCompleteLog. I'll land a requestCompleteLog for macOS and see if it fixes the problem.

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2ab411552083
requestCompleteLog for browser_primaryUI.js to see if it fixes timeouts. r=intermittent

Comment 25

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/2ab411552083

Comment 26

[Intermittent Failures Robot]

17 failures in 657 pushes (0.026 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 12
* mozilla-central: 3
* mozilla-inbound: 2

Platform breakdown:
* osx-10-10: 13
* windows7-32: 3
* linux64-jsdcov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-15&endday=2018-01-21&tree=all

Comment 27

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1425394&startday=2018-01-22&endday=2018-01-28&tree=all