Closed Bug 1350273 Opened 7 years ago Closed 7 years ago

Intermittent Automation Error: mozprocess timed out after 600 seconds running ['python2.7', 'worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', 'worker/workspace/build/.android/releng.manifest'...

Categories

(Testing :: General, defect)

Version 3
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: bulk-close-intermittents, intermittent-failure, Whiteboard: [stockwell infra])

over 60 instances so far in 3+ hours, is this infra?  happens on many different android debug jobs.
Whiteboard: [stockwell needswork]
[task 2017-03-24T02:45:57.925193Z] 02:45:57     INFO - Running command: ['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache'] in /home/worker/workspace/build/.android
[task 2017-03-24T02:45:57.926171Z] 02:45:57     INFO - Copy/paste: /usr/bin/python2.7 /home/worker/workspace/build/tooltool.py --url http://relengapi/tooltool/ fetch -m /home/worker/workspace/build/.android/releng.manifest -o -c /home/worker/tooltool_cache
[task 2017-03-24T02:45:57.927266Z] 02:45:57     INFO - Calling ['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache'] with output_timeout 600
[task 2017-03-24T02:45:58.201017Z] 02:45:58     INFO -  INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /home/worker/tooltool_cache
[task 2017-03-24T02:45:58.202149Z] 02:45:58     INFO -  INFO - Attempting to fetch from 'http://relengapi/tooltool/'...
[task 2017-03-24T02:55:58.302206Z] 02:55:58     INFO - Automation Error: mozprocess timed out after 600 seconds running ['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache']
[task 2017-03-24T02:55:58.329533Z] 02:55:58    ERROR - timed out after 600 seconds of no output
[task 2017-03-24T02:55:58.329904Z] 02:55:58    ERROR - Return code: -9
[task 2017-03-24T02:55:58.330393Z] 02:55:58     INFO - retry: Failed, sleeping 60 seconds before retrying
[task 2017-03-24T02:56:58.342161Z] 02:56:58     INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x16a5950>, '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 0x11cc8e0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x16a70e0>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/home/worker/workspace/build/.android', 'privileged': False}, attempt #2
[task 2017-03-24T02:56:58.342262Z] 02:56:58     INFO - Running command: ['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache'] in /home/worker/workspace/build/.android
[task 2017-03-24T02:56:58.342389Z] 02:56:58     INFO - Copy/paste: /usr/bin/python2.7 /home/worker/workspace/build/tooltool.py --url http://relengapi/tooltool/ fetch -m /home/worker/workspace/build/.android/releng.manifest -o -c /home/worker/tooltool_cache
[task 2017-03-24T02:56:58.342645Z] 02:56:58     INFO - Calling ['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache'] with output_timeout 600
[task 2017-03-24T02:56:58.392823Z] 02:56:58     INFO -  INFO - File AVDs-armv7a-android-4.3.1_r1-build-2016-08-02.tar.gz not present in local cache folder /home/worker/tooltool_cache
[task 2017-03-24T02:56:58.393076Z] 02:56:58     INFO -  INFO - Attempting to fetch from 'http://relengapi/tooltool/'...
[task 2017-03-24T02:57:59.560363Z] 02:57:59    ERROR -  Traceback (most recent call last):
[task 2017-03-24T02:57:59.561317Z] 02:57:59     INFO -    File "/home/worker/workspace/build/tooltool.py", line 1034, in <module>
[task 2017-03-24T02:57:59.562373Z] 02:57:59     INFO -      sys.exit(main(sys.argv))
[task 2017-03-24T02:57:59.562492Z] 02:57:59     INFO -    File "/home/worker/workspace/build/tooltool.py", line 1031, in main
[task 2017-03-24T02:57:59.562555Z] 02:57:59     INFO -      return 0 if process_command(options, args) else 1
[task 2017-03-24T02:57:59.562622Z] 02:57:59     INFO -    File "/home/worker/workspace/build/tooltool.py", line 932, in process_command
[task 2017-03-24T02:57:59.563576Z] 02:57:59     INFO -      region=options.get('region'))
[task 2017-03-24T02:57:59.563646Z] 02:57:59     INFO -    File "/home/worker/workspace/build/tooltool.py", line 636, in fetch_files
[task 2017-03-24T02:57:59.563721Z] 02:57:59     INFO -      temp_file_name = fetch_file(base_urls, f, auth_file=auth_file, region=region)
[task 2017-03-24T02:57:59.563805Z] 02:57:59     INFO -    File "/home/worker/workspace/build/tooltool.py", line 480, in fetch_file
[task 2017-03-24T02:57:59.564214Z] 02:57:59     INFO -      f = urllib2.urlopen(req)
[task 2017-03-24T02:57:59.566726Z] 02:57:59     INFO -    File "/usr/lib/python2.7/urllib2.py", line 126, in urlopen
[task 2017-03-24T02:57:59.566833Z] 02:57:59     INFO -      return _opener.open(url, data, timeout)
[task 2017-03-24T02:57:59.566956Z] 02:57:59     INFO -    File "/usr/lib/python2.7/urllib2.py", line 400, in open
[task 2017-03-24T02:57:59.567063Z] 02:57:59     INFO -      response = self._open(req, data)
[task 2017-03-24T02:57:59.567157Z] 02:57:59     INFO -    File "/usr/lib/python2.7/urllib2.py", line 418, in _open
[task 2017-03-24T02:57:59.567247Z] 02:57:59     INFO -      '_open', req)
[task 2017-03-24T02:57:59.567304Z] 02:57:59     INFO -    File "/usr/lib/python2.7/urllib2.py", line 378, in _call_chain
[task 2017-03-24T02:57:59.567346Z] 02:57:59     INFO -      result = func(*args)
[task 2017-03-24T02:57:59.567395Z] 02:57:59     INFO -    File "/usr/lib/python2.7/urllib2.py", line 1207, in http_open
[task 2017-03-24T02:57:59.567448Z] 02:57:59     INFO -      return self.do_open(httplib.HTTPConnection, req)
[task 2017-03-24T02:57:59.567498Z] 02:57:59     INFO -    File "/usr/lib/python2.7/urllib2.py", line 1180, in do_open
[task 2017-03-24T02:57:59.567551Z] 02:57:59     INFO -      r = h.getresponse(buffering=True)
[task 2017-03-24T02:57:59.567834Z] 02:57:59     INFO -    File "/usr/lib/python2.7/httplib.py", line 1076, in getresponse
[task 2017-03-24T02:57:59.568159Z] 02:57:59     INFO -      response.begin()
[task 2017-03-24T02:57:59.568504Z] 02:57:59     INFO -    File "/usr/lib/python2.7/httplib.py", line 444, in begin
[task 2017-03-24T02:57:59.568798Z] 02:57:59     INFO -      version, status, reason = self._read_status()
[task 2017-03-24T02:57:59.569071Z] 02:57:59     INFO -    File "/usr/lib/python2.7/httplib.py", line 408, in _read_status
[task 2017-03-24T02:57:59.569383Z] 02:57:59     INFO -      raise BadStatusLine(line)
[task 2017-03-24T02:57:59.569667Z] 02:57:59     INFO -  httplib.BadStatusLine: ''
[task 2017-03-24T02:57:59.621417Z] 02:57:59    ERROR - Return code: 1
[task 2017-03-24T02:57:59.621744Z] 02:57:59     INFO - retry: Failed, sleeping 120 seconds before retrying
[task 2017-03-24T02:59:59.634595Z] 02:59:59     INFO - retry: Calling run_command with args: (['/usr/bin/python2.7', '/home/worker/workspace/build/tooltool.py', '--url', 'http://relengapi/tooltool/', 'fetch', '-m', '/home/worker/workspace/build/.android/releng.manifest', '-o', '-c', '/home/worker/tooltool_cache'],), kwargs: {'output_timeout': 600, 'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x16a5950>, '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 0x11cc8e0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x16a70e0>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/home/worker/workspace/build/.android', 'privileged': False}, attempt #3


it sounds like tooltool is not available, why is this only happening on android builds, not desktop?
Whiteboard: [stockwell needswork] → [stockwell infra]
:catlee, can you help find someone to look at this?
Flags: needinfo?(catlee)
(In reply to Joel Maher ( :jmaher) from comment #3)
> it sounds like tooltool is not available, why is this only happening on
> android builds, not desktop?

It seems like it was a temporary outage. Current jobs look okay.

Android jobs use tooltool to get AVDs and SDK binaries. I'm not sure if desktop jobs depend on tooltool.
I took a look at some relengapi logs, and couldn't find anything corresponding with the errors here :(

If you can get a list of times (with timezones!) when the failures happened, we can look at more backend logs.
Flags: needinfo?(catlee)
Fetch initiation times from a few randomly selected logs, sorted:

2017-03-24T02:44:29.433280Z
2017-03-24T02:44:35.479054Z
2017-03-24T02:45:18.837556Z
2017-03-24T02:45:18.996656Z
2017-03-24T02:46:08.793581Z
2017-03-24T02:47:26.750680Z
2017-03-24T02:47:30.274413Z
2017-03-24T02:47:32.885980Z
2017-03-24T02:47:37.783973Z
2017-03-24T02:47:54.571909Z

Those should all be in UTC.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.