1479911 - Intermittent Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', ' /runtests.py', '--total-chunks', '7', '--this-chunk', '3', '--jscov-dir-prefix= /blobber_upload_dir', '--appname= /fi

Status: RESOLVED DUPLICATE of bug 1475525

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com

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

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

[task 2018-07-31T20:39:38.446Z] 20:39:38     INFO - TEST-START | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors.js
[task 2018-07-31T20:39:40.187Z] 20:39:40     INFO - GECKO(8061) | Collecting coverage for: chrome://mochitests/content/browser/toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors.js
[task 2018-07-31T20:39:40.909Z] 20:39:40     INFO - GECKO(8061) | Writing coverage to: /builds/worker/workspace/build/blobber_upload_dir/jscov_1533069580904.json
[task 2018-07-31T20:39:40.974Z] 20:39:40     INFO - GECKO(8061) | MEMORY STAT | vsize 1897MB | residentFast 365MB | heapAllocated 122MB
[task 2018-07-31T20:39:40.974Z] 20:39:40     INFO - TEST-OK | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors.js | took 2522ms
[task 2018-07-31T20:39:40.994Z] 20:39:40     INFO - checking window state
[task 2018-07-31T20:39:41.010Z] 20:39:41     INFO - TEST-START | toolkit/components/extensions/test/browser/browser_ext_themes_ntp_colors_perwindow.js
[task 2018-07-31T20:56:21.036Z] 20:56:21     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--total-chunks', '7', '--this-chunk', '3', '--jscov-dir-prefix=/builds/worker/workspace/build/blobber_upload_dir', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/dwOGGpMaRga1H4izlrt4Og/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/browser-chrome-coverage_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/browser-chrome-coverage_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime', '--timeout=1200']
[task 2018-07-31T20:56:21.056Z] 20:56:21    ERROR - timed out after 1000 seconds of no output
[task 2018-07-31T20:56:21.056Z] 20:56:21    ERROR - Return code: -15
[task 2018-07-31T20:56:21.057Z] 20:56:21    ERROR - No suite end message was emitted by this harness.
[task 2018-07-31T20:56:21.058Z] 20:56:21     INFO - TinderboxPrint: mochitest-browser-chrome-coverage<br/>299/0/0
[task 2018-07-31T20:56:21.058Z] 20:56:21    ERROR - # TBPL FAILURE #
[task 2018-07-31T20:56:21.058Z] 20:56:21  WARNING - setting return code to 2
[task 2018-07-31T20:56:21.058Z] 20:56:21    ERROR - The mochitest suite: browser-chrome-coverage ran with return status: FAILURE
[task 2018-07-31T20:56:21.059Z] 20:56:21     INFO - Running post-action listener: _package_coverage_data
[task 2018-07-31T20:56:21.062Z] 20:56:21     INFO - Beginning compression of JSDCov artifacts...
[task 2018-07-31T20:56:26.526Z] 20:56:26     INFO - Completed compression of JSDCov artifacts!
[task 2018-07-31T20:56:26.526Z] 20:56:26     INFO - Path to JSDCov compressed artifacts: /builds/worker/workspace/build/blobber_upload_dir/jsdcov_artifacts.zip
[task 2018-07-31T20:56:26.526Z] 20:56:26     INFO - Running post-action listener: _resource_record_post_action
[task 2018-07-31T20:56:26.526Z] 20:56:26     INFO - [mozharness: 2018-07-31 20:56:26.526708Z] Finished run-tests step (success)
[task 2018-07-31T20:56:26.527Z] 20:56:26     INFO - Running post-run listener: _resource_record_post_run
[task 2018-07-31T20:56:26.664Z] 20:56:26     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2018-07-31T20:56:26.670Z] 20:56:26     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 14.79151855723994}, {"name": "io_write_bytes", "value": 2431827968}, {"name": "io.read_bytes", "value": 245760}, {"name": "io_write_time", "value": 248992}, {"name": "io_read_time", "value": 12}], "extraOptions": ["e10s", "taskcluster-m3.xlarge"], "name": "mochitest.browser-chrome-coverage.3.overall"}, {"subtests": [{"name": "time", "value": 16.412304878234863}, {"name": "cpu_percent", "value": 25.140625}], "name": "mochitest.browser-chrome-coverage.3.install"}, {"subtests": [{"name": "time", "value": 0.0005259513854980469}], "name": "mochitest.browser-chrome-coverage.3.stage-files"}, {"subtests": [{"name": "time", "value": 1899.8695709705353}, {"name": "cpu_percent", "value": 14.697112341772153}], "name": "mochitest.browser-chrome-coverage.3.run-tests"}]}
[task 2018-07-31T20:56:26.670Z] 20:56:26     INFO - Total resource usage - Wall time: 1916s; CPU: 15.0%; Read bytes: 245760; Write bytes: 2431827968; Read time: 12; Write time: 248992
[task 2018-07-31T20:56:26.670Z] 20:56:26     INFO - TinderboxPrint: CPU usage<br/>14.7%
[task 2018-07-31T20:56:26.670Z] 20:56:26     INFO - TinderboxPrint: I/O read bytes / time<br/>245,760 / 12
[task 2018-07-31T20:56:26.671Z] 20:56:26     INFO - TinderboxPrint: I/O write bytes / time<br/>2,431,827,968 / 248,992
[task 2018-07-31T20:56:26.671Z] 20:56:26     INFO - TinderboxPrint: CPU idle<br/>6,401.9 (85.2%)
[task 2018-07-31T20:56:26.671Z] 20:56:26     INFO - TinderboxPrint: CPU system<br/>136.0 (1.8%)
[task 2018-07-31T20:56:26.671Z] 20:56:26     INFO - TinderboxPrint: CPU user<br/>962.2 (12.8%)
[task 2018-07-31T20:56:26.671Z] 20:56:26     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2018-07-31T20:56:26.673Z] 20:56:26     INFO - install - Wall time: 16s; CPU: 25.0%; Read bytes: 0; Write bytes: 13529088; Read time: 0; Write time: 2120
[task 2018-07-31T20:56:26.674Z] 20:56:26     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2018-07-31T20:56:26.695Z] 20:56:26     INFO - run-tests - Wall time: 1900s; CPU: 15.0%; Read bytes: 245760; Write bytes: 2371588096; Read time: 12; Write time: 166960
[task 2018-07-31T20:56:27.289Z] 20:56:27     INFO - Running post-run listener: copy_logs_to_upload_dir
[task 2018-07-31T20:56:27.289Z] 20:56:27     INFO - Copying logs to upload dir...
[task 2018-07-31T20:56:27.289Z] 20:56:27     INFO - mkdir: /builds/worker/workspace/build/upload/logs
[task 2018-07-31T20:56:27.292Z] 20:56:27     INFO - Copying logs to upload dir...
[task 2018-07-31T20:56:27.294Z] 20:56:27  WARNING - returning nonzero exit status 2
[task 2018-07-31T20:56:27.315Z] cleanup