Closed Bug 1443978 Opened 8 years ago Closed 3 years ago

Intermittent Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace

Categories

(Release Engineering :: Applications: MozharnessCore, defect, P5)

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: csabou [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=166568443&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/WOC2hq9FRECtJ_pDnBlqgA/runs/0/artifacts/public/logs/live_backing.log [task 2018-03-07T19:53:17.980Z] 19:53:17 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [task 2018-03-07T20:03:18.002Z] 20:03:18 INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] [task 2018-03-07T20:03:18.010Z] 20:03:18 ERROR - timed out after 600 seconds of no output [task 2018-03-07T20:03:18.011Z] 20:03:18 ERROR - Return code: -15 [task 2018-03-07T20:03:18.011Z] 20:03:18 INFO - retry: Failed, sleeping 60 seconds before retrying [task 2018-03-07T20:04:18.021Z] 20:04:18 INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fade24d2408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fade3f61c48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7fade24f53d8>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build/.android', 'privileged': False}, attempt #2 [task 2018-03-07T20:04:18.021Z] 20:04:18 INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] in /builds/worker/workspace/build/.android [task 2018-03-07T20:04:18.021Z] 20:04:18 INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/.android/releng.manifest -o -c /builds/worker/tooltool_cache [task 2018-03-07T20:04:18.021Z] 20:04:18 INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] with output_timeout 600 [task 2018-03-07T20:04:18.069Z] 20:04:18 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /builds/worker/tooltool_cache [task 2018-03-07T20:04:18.069Z] 20:04:18 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [task 2018-03-07T20:04:25.006Z] 20:04:25 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz fetched from http://relengapi/tooltool/ as /builds/worker/workspace/build/.android/tmpVWG5rH [task 2018-03-07T20:04:26.154Z] 20:04:26 INFO - INFO - File integrity verified, renaming tmpVWG5rH to AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz [task 2018-03-07T20:04:26.155Z] 20:04:26 INFO - INFO - Updating local cache /builds/worker/tooltool_cache... [task 2018-03-07T20:04:26.299Z] 20:04:26 INFO - INFO - Local cache /builds/worker/tooltool_cache updated with AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz [task 2018-03-07T20:04:26.303Z] 20:04:26 INFO - INFO - untarring "AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz" [task 2018-03-07T20:04:31.692Z] 20:04:31 INFO - Return code: 0 [task 2018-03-07T20:04:31.728Z] 20:04:31 INFO - Running post-action listener: _resource_record_post_action [task 2018-03-07T20:04:31.728Z] 20:04:31 INFO - [mozharness: 2018-03-07 20:04:31.728765Z] Finished setup-avds step (success) [task 2018-03-07T20:04:31.729Z] 20:04:31 INFO - [mozharness: 2018-03-07 20:04:31.728917Z] Running start-emulator step. [task 2018-03-07T20:04:31.729Z] 20:04:31 INFO - Running pre-action listener: _resource_record_pre_action [task 2018-03-07T20:04:31.729Z] 20:04:31 INFO - Running main action method: start_emulator [task 2018-03-07T20:04:31.729Z] 20:04:31 INFO - Writing to file /builds/worker/workspace/build/tooltool.tt [task 2018-03-07T20:04:31.730Z] 20:04:31 INFO - Contents: [task 2018-03-07T20:04:31.730Z] 20:04:31 INFO - [task 2018-03-07T20:04:31.730Z] 20:04:31 INFO - [ [task 2018-03-07T20:04:31.730Z] 20:04:31 INFO - { [task 2018-03-07T20:04:31.730Z] 20:04:31 INFO - "size": 38451805, [task 2018-03-07T20:04:31.730Z] 20:04:31 INFO - "digest": "ac3000aa6846dd1b09a420a1ba84727e393036f49da1419d6c9e5ec2490fc6105c74ca18b616c465dbe693992e2939afd88bc2042d961a9050a3cafd2a673ff4", [task 2018-03-07T20:04:31.731Z] 20:04:31 INFO - "algorithm": "sha512", [task 2018-03-07T20:04:31.731Z] 20:04:31 INFO - "filename": "android-sdk_r24.0.2a-linux.tar.gz", [task 2018-03-07T20:04:31.731Z] 20:04:31 INFO - "unpack": "True" [task 2018-03-07T20:04:31.731Z] 20:04:31 INFO - } [task 2018-03-07T20:04:31.731Z] 20:04:31 INFO - ]
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=175197376&repo=autoland&lineNumber=677 [task 2018-04-23T22:11:35.449Z] 22:11:35 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /builds/worker/tooltool_cache [task 2018-04-23T22:11:35.450Z] 22:11:35 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [task 2018-04-23T22:11:38.938Z] compiz (core) - Warn: Attempted to restack relative to 0x1400006 which is not a child of the root window or a window compiz owns [task 2018-04-23T22:21:35.472Z] 22:21:35 INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] [task 2018-04-23T22:21:35.474Z] 22:21:35 ERROR - timed out after 600 seconds of no output [task 2018-04-23T22:21:35.474Z] 22:21:35 ERROR - Return code: -15 [task 2018-04-23T22:21:35.474Z] 22:21:35 INFO - retry: Failed, sleeping 60 seconds before retrying [task 2018-04-23T22:22:35.493Z] 22:22:35 INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9c8a408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2bb719c48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9cac510>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build/.android', 'privileged': False}, attempt #2 [task 2018-04-23T22:22:35.494Z] 22:22:35 INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] in /builds/worker/workspace/build/.android [task 2018-04-23T22:22:35.494Z] 22:22:35 INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/.android/releng.manifest -o -c /builds/worker/tooltool_cache [task 2018-04-23T22:22:35.494Z] 22:22:35 INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] with output_timeout 600 [task 2018-04-23T22:22:35.545Z] 22:22:35 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /builds/worker/tooltool_cache [task 2018-04-23T22:22:35.545Z] 22:22:35 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [task 2018-04-23T22:32:35.567Z] 22:32:35 INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] [task 2018-04-23T22:32:35.568Z] 22:32:35 ERROR - timed out after 600 seconds of no output [task 2018-04-23T22:32:35.568Z] 22:32:35 ERROR - Return code: -15 [task 2018-04-23T22:32:35.568Z] 22:32:35 INFO - retry: Failed, sleeping 120 seconds before retrying [task 2018-04-23T22:34:35.571Z] 22:34:35 INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9c8a408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2bb719c48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9cac510>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build/.android', 'privileged': False}, attempt #3 [task 2018-04-23T22:34:35.571Z] 22:34:35 INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] in /builds/worker/workspace/build/.android [task 2018-04-23T22:34:35.571Z] 22:34:35 INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/.android/releng.manifest -o -c /builds/worker/tooltool_cache [task 2018-04-23T22:34:35.571Z] 22:34:35 INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] with output_timeout 600 [task 2018-04-23T22:34:35.618Z] 22:34:35 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /builds/worker/tooltool_cache [task 2018-04-23T22:34:35.619Z] 22:34:35 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [task 2018-04-23T22:44:35.658Z] 22:44:35 INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] [task 2018-04-23T22:44:35.670Z] 22:44:35 ERROR - timed out after 600 seconds of no output [task 2018-04-23T22:44:35.670Z] 22:44:35 ERROR - Return code: -15 [task 2018-04-23T22:44:35.670Z] 22:44:35 INFO - retry: Failed, sleeping 240 seconds before retrying [task 2018-04-23T22:48:35.685Z] 22:48:35 INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9c8a408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2bb719c48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9cac510>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build/.android', 'privileged': False}, attempt #4 [task 2018-04-23T22:48:35.685Z] 22:48:35 INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] in /builds/worker/workspace/build/.android [task 2018-04-23T22:48:35.686Z] 22:48:35 INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/.android/releng.manifest -o -c /builds/worker/tooltool_cache [task 2018-04-23T22:48:35.686Z] 22:48:35 INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] with output_timeout 600 [task 2018-04-23T22:48:35.737Z] 22:48:35 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /builds/worker/tooltool_cache [task 2018-04-23T22:48:35.737Z] 22:48:35 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [task 2018-04-23T22:58:35.764Z] 22:58:35 INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] [task 2018-04-23T22:58:35.788Z] 22:58:35 ERROR - timed out after 600 seconds of no output [task 2018-04-23T22:58:35.788Z] 22:58:35 ERROR - Return code: -15 [task 2018-04-23T22:58:35.788Z] 22:58:35 INFO - retry: Failed, sleeping 300 seconds before retrying [task 2018-04-23T23:03:35.804Z] 23:03:35 INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9c8a408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2bb719c48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7fa2b9cac510>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build/.android', 'privileged': False}, attempt #5 [task 2018-04-23T23:03:35.805Z] 23:03:35 INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] in /builds/worker/workspace/build/.android [task 2018-04-23T23:03:35.805Z] 23:03:35 INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/.android/releng.manifest -o -c /builds/worker/tooltool_cache [task 2018-04-23T23:03:35.805Z] 23:03:35 INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/builds/worker/tooltool_cache'] with output_timeout 600 [task 2018-04-23T23:03:35.853Z] 23:03:35 INFO - INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /builds/worker/tooltool_cache [task 2018-04-23T23:03:35.853Z] 23:03:35 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'... [taskcluster:error] Task timeout after 3600 seconds. Force killing container. [taskcluster 2018-04-23 23:11:15.527Z] === Task Finished === [taskcluster 2018-04-23 23:11:15.528Z] Unsuccessful task run with exit code: -1 completed in 3928.075 seconds
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
:apavel looks like this are intermittent errors which are happening very rarely.
Status: REOPENED → RESOLVED
Closed: 8 years ago8 years ago
Resolution: --- → WORKSFORME
(In reply to Rok Garbas [:garbas] from comment #10) > :apavel looks like this are intermittent errors which are happening very > rarely. Yes, it appears so.
Status: REOPENED → RESOLVED
Closed: 8 years ago8 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=222133727&repo=autoland&lineNumber=916

[task 2019-01-16T03:56:17.410Z] 03:56:17 INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/hostutils/releng.manifest', '-o', '-c', '/builds/worker/tooltool-cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7f9c8b5f9408>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x7f9c8c2ffc48>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x7f9c8c26a510>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/worker/workspace/build/hostutils', 'privileged': False}, attempt #1
[task 2019-01-16T03:56:17.410Z] 03:56:17 INFO - Running command: ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/hostutils/releng.manifest', '-o', '-c', '/builds/worker/tooltool-cache'] in /builds/worker/workspace/build/hostutils
[task 2019-01-16T03:56:17.410Z] 03:56:17 INFO - Copy/paste: /usr/bin/python2.7 -u /builds/worker/workspace/mozharness/external_tools/tooltool.py --url http://relengapi/tooltool/ fetch -m /builds/worker/workspace/build/hostutils/releng.manifest -o -c /builds/worker/tooltool-cache
[task 2019-01-16T03:56:17.411Z] 03:56:17 INFO - Calling ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/hostutils/releng.manifest', '-o', '-c', '/builds/worker/tooltool-cache'] with output_timeout 600
[task 2019-01-16T03:56:17.461Z] 03:56:17 INFO - INFO - File host-utils-66.0a1.en-US.linux-x86_64.tar.gz not present in local cache folder /builds/worker/tooltool-cache
[task 2019-01-16T03:56:17.461Z] 03:56:17 INFO - INFO - Attempting to fetch from 'http://relengapi/tooltool/'...
[task 2019-01-16T04:06:17.491Z] 04:06:17 INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '-u', '/builds/worker/workspace/mozharness/external_tools/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/builds/worker/workspace/build/hostutils/releng.manifest', '-o', '-c', '/builds/worker/tooltool-cache']
[task 2019-01-16T04:06:17.522Z] 04:06:17 ERROR - timed out after 600 seconds of no output
[task 2019-01-16T04:06:17.522Z] 04:06:17 ERROR - Return code: -15
[task 2019-01-16T04:06:17.522Z] 04:06:17 INFO - retry: Failed, sleeping 60 seconds before retrying

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 8 years ago7 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 7 years ago6 years ago
Resolution: --- → INCOMPLETE

Looks like this failure is present also on green runs: https://treeherder.mozilla.org/logviewer?job_id=332646144&repo=autoland&lineNumber=964 so it's not relevant for the classified failures here. Gonna re-classify. Failures were all Bug 1589796.

Andrew, looks like these timeouts started occurring after Bug 1369784 and Bug 1646161 landed here. Could you have a look over these?

Flags: needinfo?(ahal)

It should be impossible for a change in mozlint (lint infrastructure) to affect tests like mochitest. Likely further retriggers will show another push is the culprit or the error is due to some external factor and that push happened to be at the wrong place at the wrong time.

Flags: needinfo?(ahal)

These failures have started appearing recently starting with this merge . So far they are only failing on Android 8 as tier 2.

These failures are almost exclusively on android-hw, when downloading host-utils from tooltool. Most android-hw and android-em test tasks download host-utils this way.

host-utils is about 100 MB in size. For android-em tasks, host-utils is typically downloaded and extracted in a few seconds. On android-hw, host-utils downloads typically take 4 to 6 minutes. In many of the failure logs for this bug, tooltool runs for 10 minutes, times out, retries, might run tooltool and timeout again after 10 minutes, eventually succeeds, but then the task exceeds its max-run-time (having run perhaps 30 minutes extra downloading host-utils).

At first I thought a shorter tooltool timeout might be helpful: retry sooner, might succeed sooner if tooltool is hung. But, as the timeout is an output timeout, and tooltool doesn't produce any progress output, and typical android-hw downloads take 4-6 minutes anyway, there's not much room to reduce the timeout, and doing so might cause more retries / more failures.

Increasing the tooltool timeout might be helpful, if those timed-out downloads are actually progressing but just needed more time. But if those tooltool sessions are actually hung, increasing the timeout will make things worse.

Overall, I think the 10 minute tooltool timeout is sensible in this case.

Another solution would be to increase the android-hw mochitest and reftest (and maybe other) max-run-time: In case it takes several attempts and 30+ minutes to download host-utils, allow the tasks to run that much longer.

Ideally, it would be nice to remove this reliance on tooltool; can we use a fetch instead; would that work any better?

https://searchfox.org/mozilla-central/rev/380fc5571b039fd453b45bbb64ed13146fe9b066/testing/mozharness/mozharness/mozilla/tooltool.py#63

Severity: normal → S3
Status: REOPENED → RESOLVED
Closed: 6 years ago3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.