Closed Bug 1479967 Opened 7 years ago Closed 7 years ago

Intermittent Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/reftest/runreftest.py', '--total-chunks', '8', '--this-chunk', '8', '--appname=/b

Categories

(Testing :: Reftest, defect, P5)

Product:
Testing
Component:
Reftest
Version:
Version 3
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1436237

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: btara [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=191259381&repo=mozilla-central https://queue.taskcluster.net/v1/task/HFGmJYsdQMqISu1ELEFK4g/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/HFGmJYsdQMqISu1ELEFK4g/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1&only_show_unexpected=1 [task 2018-07-31T22:43:23.504Z] 22:43:23 INFO - REFTEST INFO | Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -profile /tmp/tmpS83T_s.mozrunner [task 2018-07-31T22:43:25.343Z] 22:43:25 INFO - 1533077005339 Marionette DEBUG Received observer notification profile-after-change [task 2018-07-31T22:43:25.978Z] 22:43:25 INFO - 1533077005972 Marionette DEBUG Received observer notification command-line-startup [task 2018-07-31T22:43:25.979Z] 22:43:25 INFO - 1533077005973 Marionette DEBUG Received observer notification nsPref:changed [task 2018-07-31T22:43:25.980Z] 22:43:25 INFO - 1533077005973 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false) [task 2018-07-31T22:43:26.489Z] 22:43:26 INFO - 1533077006484 Marionette DEBUG Received observer notification toplevel-window-ready [task 2018-07-31T22:43:30.240Z] 22:43:30 INFO - 1533077010235 Marionette DEBUG Received observer notification sessionstore-windows-restored [task 2018-07-31T22:43:30.240Z] 22:43:30 INFO - 1533077010236 Marionette DEBUG Waiting for delayed startup... [task 2018-07-31T22:43:31.431Z] 22:43:31 INFO - 1533077011426 Marionette DEBUG Waiting for startup tests... [task 2018-07-31T22:43:33.192Z] 22:43:33 INFO - 1533077013186 Marionette INFO Listening on port 2828 [task 2018-07-31T22:43:33.193Z] 22:43:33 INFO - 1533077013187 Marionette DEBUG Remote service is active [task 2018-07-31T22:43:33.367Z] 22:43:33 INFO - 1533077013340 Marionette DEBUG Accepted connection 0 from 127.0.0.1:40574 [task 2018-07-31T22:43:33.369Z] 22:43:33 INFO - 1533077013360 Marionette DEBUG Accepted connection 1 from 127.0.0.1:40576 [task 2018-07-31T22:43:33.375Z] 22:43:33 INFO - 1533077013363 Marionette DEBUG Closed connection 0 [task 2018-07-31T22:43:33.390Z] 22:43:33 INFO - 1533077013387 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-07-31T22:43:33.782Z] 22:43:33 INFO - 1533077013776 Marionette DEBUG [4294967297] Frame script loaded [task 2018-07-31T22:43:33.830Z] 22:43:33 INFO - 1533077013824 Marionette DEBUG [4294967297] Frame script registered [task 2018-07-31T22:43:33.929Z] 22:43:33 INFO - 1533077013922 Marionette TRACE 1 <- [1,1,null,{"sessionId":"211199fa-b854-41b0-999c-1e526a5e5618","capabilities":{"browserName":"firefox","browserVersion":"63.0a ... essID":935,"moz:profile":"/tmp/tmpS83T_s.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-07-31T22:43:34.007Z] 22:43:34 INFO - 1533077013996 Marionette TRACE 1 -> [0,2,"Addon:Install",{"path":"/builds/worker/workspace/build/tests/reftest/reftest","temporary":true}] [task 2018-07-31T22:43:34.085Z] 22:43:34 INFO - 1533077014076 Marionette TRACE 1 <- [1,2,null,{"value":"reftest@mozilla.org"}] [task 2018-07-31T22:43:34.332Z] 22:43:34 INFO - 1533077014327 Marionette TRACE 1 -> [0,3,"WebDriver:DeleteSession",{}] [task 2018-07-31T22:43:34.340Z] 22:43:34 INFO - 1533077014335 Marionette TRACE 1 <- [1,3,null,{"value":null}] [task 2018-07-31T22:43:34.364Z] 22:43:34 INFO - 1533077014361 Marionette DEBUG Closed connection 1 [task 2018-07-31T22:43:36.365Z] 22:43:36 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0108,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:36.367Z] 22:43:36 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:37.250Z] 22:43:37 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x700001,name=PScriptCache::Msg___delete__) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:39.242Z] 22:43:39 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0107,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:39.245Z] 22:43:39 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0108,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:39.246Z] 22:43:39 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:44.095Z] 22:43:44 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0107,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:44.096Z] 22:43:44 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:46.090Z] 22:43:46 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0107,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:46.091Z] 22:43:46 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0108,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:46.092Z] 22:43:46 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0109,name=PContent::Msg_UpdateChildScalars) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:46.093Z] 22:43:46 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:49.571Z] 22:43:49 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x560027,name=PNecko::Msg_RemoveRequestContext) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:50.402Z] 22:43:50 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0107,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:50.404Z] 22:43:50 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0109,name=PContent::Msg_UpdateChildScalars) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:50.410Z] 22:43:50 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:52.401Z] 22:43:52 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0107,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:52.405Z] 22:43:52 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0108,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:43:52.407Z] 22:43:52 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:44:15.709Z] 22:44:15 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0109,name=PContent::Msg_UpdateChildScalars) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:44:15.717Z] 22:44:15 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:44:30.786Z] 22:44:30 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E0107,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T22:44:30.789Z] 22:44:30 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2E010C,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-07-31T23:01:10.819Z] 23:01:10 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/reftest/runreftest.py', '--total-chunks', '8', '--this-chunk', '8', '--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/fA4qH59RS4W6k6ENmpHnEQ/artifacts/public/build/target.crashreporter-symbols.zip', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/reftest-no-accel_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/reftest-no-accel_errorsummary.log', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--suite=reftest', '--setpref=layers.acceleration.disabled=true', '--', 'tests/reftest/tests/layout/reftests/reftest.list'] [task 2018-07-31T23:01:10.858Z] 23:01:10 ERROR - timed out after 1000 seconds of no output [task 2018-07-31T23:01:10.860Z] 23:01:10 ERROR - Return code: -15 [task 2018-07-31T23:01:10.861Z] 23:01:10 ERROR - No checks run. [task 2018-07-31T23:01:10.863Z] 23:01:10 ERROR - No suite end message was emitted by this harness. [task 2018-07-31T23:01:10.864Z] 23:01:10 INFO - TinderboxPrint: reftest-reftest-no-accel<br/><em class="testfail">T-FAIL</em> [task 2018-07-31T23:01:10.866Z] 23:01:10 ERROR - # TBPL FAILURE # [task 2018-07-31T23:01:10.870Z] 23:01:10 WARNING - setting return code to 2 [task 2018-07-31T23:01:10.872Z] 23:01:10 ERROR - The reftest suite: reftest-no-accel ran with return status: FAILURE [task 2018-07-31T23:01:10.874Z] 23:01:10 INFO - Running post-action listener: _package_coverage_data [task 2018-07-31T23:01:10.875Z] 23:01:10 INFO - Running post-action listener: _resource_record_post_action [task 2018-07-31T23:01:10.877Z] 23:01:10 INFO - [mozharness: 2018-07-31 23:01:10.855386Z] Finished run-tests step (success) [task 2018-07-31T23:01:10.879Z] 23:01:10 INFO - Running post-run listener: _resource_record_post_run [task 2018-07-31T23:01:11.024Z] 23:01:11 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json [task 2018-07-31T23:01:11.035Z] 23:01:11 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 50.835079225352}, {"name": "io_write_bytes", "value": 2073628672}, {"name": "io.read_bytes", "value": 10596352}, {"name": "io_write_time", "value": 382536}, {"name": "io_read_time", "value": 688}], "extraOptions": ["e10s", "taskcluster-m3.large"], "name": "reftest.reftest-no-accel.8.overall"}, {"subtests": [{"name": "time", "value": 70.04366493225098}, {"name": "cpu_percent", "value": 50.335507246376814}], "name": "reftest.reftest-no-accel.8.install"}, {"subtests": [{"name": "time", "value": 0.0005779266357421875}], "name": "reftest.reftest-no-accel.8.stage-files"}, {"subtests": [{"name": "time", "value": 1067.9981091022491}, {"name": "cpu_percent", "value": 50.86768292682917}], "name": "reftest.reftest-no-accel.8.run-tests"}]} [task 2018-07-31T23:01:11.038Z] 23:01:11 INFO - Total resource usage - Wall time: 1138s; CPU: 51.0%; Read bytes: 10596352; Write bytes: 2073628672; Read time: 688; Write time: 382536 [task 2018-07-31T23:01:11.039Z] 23:01:11 INFO - TinderboxPrint: CPU usage<br/>50.9% [task 2018-07-31T23:01:11.041Z] 23:01:11 INFO - TinderboxPrint: I/O read bytes / time<br/>10,596,352 / 688 [task 2018-07-31T23:01:11.043Z] 23:01:11 INFO - TinderboxPrint: I/O write bytes / time<br/>2,073,628,672 / 382,536 [task 2018-07-31T23:01:11.045Z] 23:01:11 INFO - TinderboxPrint: CPU idle<br/>1,078.6 (48.1%) [task 2018-07-31T23:01:11.047Z] 23:01:11 INFO - TinderboxPrint: CPU system<br/>837.3 (37.4%) [task 2018-07-31T23:01:11.049Z] 23:01:11 INFO - TinderboxPrint: CPU user<br/>318.3 (14.2%) [task 2018-07-31T23:01:11.051Z] 23:01:11 INFO - TinderboxPrint: Swap in / out<br/>0 / 0 [task 2018-07-31T23:01:11.054Z] 23:01:11 INFO - install - Wall time: 70s; CPU: 50.0%; Read bytes: 0; Write bytes: 701800448; Read time: 0; Write time: 130024 [task 2018-07-31T23:01:11.056Z] 23:01:11 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-31T23:01:11.071Z] 23:01:11 INFO - run-tests - Wall time: 1068s; CPU: 51.0%; Read bytes: 10551296; Write bytes: 1276440576; Read time: 664; Write time: 231436 [task 2018-07-31T23:01:11.509Z] 23:01:11 INFO - Running post-run listener: copy_logs_to_upload_dir [task 2018-07-31T23:01:11.510Z] 23:01:11 INFO - Copying logs to upload dir... [task 2018-07-31T23:01:11.511Z] 23:01:11 INFO - mkdir: /builds/worker/workspace/build/upload/logs [task 2018-07-31T23:01:11.514Z] 23:01:11 INFO - Copying logs to upload dir... [task 2018-07-31T23:01:11.517Z] 23:01:11 WARNING - returning nonzero exit status 2 [task 2018-07-31T23:01:11.550Z] cleanup
This is not a Marionette test job but Reftests. So it should have been starred as bug 1436237.
Status: NEW → RESOLVED
Closed: 7 years ago
Component: Marionette → Reftest
Resolution: --- → DUPLICATE
See Also: → 1560598
You need to log in before you can comment on or make changes to this bug.