Closed Bug 1632386 Opened 4 months ago Closed 4 months ago

Intermittent condprof TimeoutError: [Errno 60] Operation timed out

Categories

(Testing :: Condprofile, defect, P5)

Version 3
defect

Tracking

(firefox77 fixed)

RESOLVED FIXED
mozilla77
Tracking Status
firefox77 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: tarek)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=298776861&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fKReIWMCQkqu45mjbQTO8Q/runs/0/artifacts/public/logs/live_backing.log


[task 2020-04-22T05:59:10.040Z] executing ['bash', '-cx', 'virtualenv/virtualenv.py -p python3 . && bin/python3 condprof/main.py --geckodriver ${MOZ_FETCHES_DIR}/geckodriver --firefox ${MOZ_FETCHES_DIR}/target.dmg ../../archive']in fetches/condprofile
[task 2020-04-22T05:59:10.043Z] + virtualenv/virtualenv.py -p python3 .
[task 2020-04-22T05:59:10.930Z] Already using interpreter /usr/local/opt/python/bin/python3.7
[task 2020-04-22T05:59:10.930Z] Using base prefix '/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7'
[task 2020-04-22T05:59:10.930Z] New python executable in /Users/cltbld/tasks/task_1587530541/fetches/condprofile/bin/python3.7
[task 2020-04-22T05:59:10.930Z] Also creating executable in /Users/cltbld/tasks/task_1587530541/fetches/condprofile/bin/python
[task 2020-04-22T05:59:10.930Z] Installing setuptools, pip, wheel...
[task 2020-04-22T05:59:13.520Z] done.
[task 2020-04-22T05:59:13.534Z] Running virtualenv with interpreter /usr/local/bin/python3
[task 2020-04-22T05:59:13.539Z] + bin/python3 condprof/main.py --geckodriver /Users/cltbld/tasks/task_1587530541/fetches/geckodriver --firefox /Users/cltbld/tasks/task_1587530541/fetches/target.dmg ../../archive
[task 2020-04-22T05:59:13.899Z] Looking in links: https://pypi.pub.build.mozilla.org/pub
[task 2020-04-22T05:59:13.900Z] Collecting pip==19.2.3 from https://files.pythonhosted.org/packages/30/db/9e38760b32e3e7f40cce46dd5fb107b8c73840df38f0046d8e6514e675a1/pip-19.2.3-py2.py3-none-any.whl
[task 2020-04-22T05:59:13.964Z]   Downloading https://files.pythonhosted.org/packages/30/db/9e38760b32e3e7f40cce46dd5fb107b8c73840df38f0046d8e6514e675a1/pip-19.2.3-py2.py3-none-any.whl (1.4MB)
[task 2020-04-22T05:59:14.186Z] Collecting setuptools==41.2.0 from https://files.pythonhosted.org/packages/b2/86/095d2f7829badc207c893dd4ac767e871f6cd547145df797ea26baea4e2e/setuptools-41.2.0-py2.py3-none-any.whl
[task 2020-04-22T05:59:14.201Z]   Downloading https://files.pythonhosted.org/packages/b2/86/095d2f7829badc207c893dd4ac767e871f6cd547145df797ea26baea4e2e/setuptools-41.2.0-py2.py3-none-any.whl (576kB)
[task 2020-04-22T05:59:14.391Z] Installing collected packages: pip, setuptools
[task 2020-04-22T05:59:14.391Z]   Found existing installation: pip 19.2.3
[task 2020-04-22T05:59:14.521Z]     Uninstalling pip-19.2.3:
[task 2020-04-22T05:59:14.553Z]       Successfully uninstalled pip-19.2.3
[task 2020-04-22T05:59:15.618Z]   Found existing installation: setuptools 41.2.0
[task 2020-04-22T05:59:15.658Z]     Uninstalling setuptools-41.2.0:
[task 2020-04-22T05:59:15.693Z]       Successfully uninstalled setuptools-41.2.0
[task 2020-04-22T05:59:15.994Z] Successfully installed pip-19.2.3 setuptools-41.2.0
[task 2020-04-22T05:59:16.792Z] Checksumming Driver Descriptor Map (DDM : 0)…
[task 2020-04-22T05:59:16.793Z]      Driver Descriptor Map (DDM : 0): verified   CRC32 $DB07AA9C
[task 2020-04-22T05:59:16.793Z] Checksumming Apple (Apple_partition_map : 1)…
[task 2020-04-22T05:59:16.794Z]      Apple (Apple_partition_map : 1): verified   CRC32 $37220574
[task 2020-04-22T05:59:16.794Z] Checksumming Macintosh (Apple_Driver_ATAPI : 2)…
[task 2020-04-22T05:59:16.795Z]   Macintosh (Apple_Driver_ATAPI : 2): verified   CRC32 $C71C0011
[task 2020-04-22T05:59:16.795Z] Checksumming Mac_OS_X (Apple_HFSX : 3)…
[task 2020-04-22T05:59:25.131Z]            Mac_OS_X (Apple_HFSX : 3): verified   CRC32 $5491E049
[task 2020-04-22T05:59:25.131Z] Checksumming  (Apple_Free : 4)…
[task 2020-04-22T05:59:26.130Z]                     (Apple_Free : 4): verified   CRC32 $00000000
[task 2020-04-22T05:59:26.132Z] verified   CRC32 $2268BB12
[task 2020-04-22T05:59:26.454Z] /dev/disk2          	Apple_partition_scheme         	
[task 2020-04-22T05:59:26.455Z] /dev/disk2s1        	Apple_partition_map            	
[task 2020-04-22T05:59:26.455Z] /dev/disk2s2        	Apple_Driver_ATAPI             	
[task 2020-04-22T05:59:26.455Z] /dev/disk2s3        	Apple_HFSX                     	/private/var/folders/1n/90df647d52l_j1z5qh6t207m000017/T/tmpmb9bdgrf
[task 2020-04-22T05:59:35.173Z] "disk2" ejected.
[task 2020-04-22T05:59:35.383Z] condprof INFO | Verifying Desktop Firefox binary
[task 2020-04-22T05:59:35.600Z] condprof INFO | Working with Firefox 77.0a1
[task 2020-04-22T05:59:35.601Z] condprof INFO | environ({'MOZ_FETCHES': '[{"artifact": "public/build/geckodriver.tar.xz", "extract": true, "task": "C6OZygamQtq0D8Eq9SBzmg"}, {"artifact": "public/build/target.condprof.tests.tar.gz", "extract": true, "task": "I4P6zQbKSgKeml2ihMC5Ew"}, {"artifact": "public/build/target.dmg", "extract": false, "task": "I4P6zQbKSgKeml2ihMC5Ew"}]', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/1n/90df647d52l_j1z5qh6t207m000017/T/', '__PYVENV_LAUNCHER__': '/usr/local/bin/python3', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.ZT0MOpk83a/Render', 'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com', 'USER': 'cltbld', 'TASK_ID': 'fKReIWMCQkqu45mjbQTO8Q', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.crm1g0RI7O/Listeners', '__CF_USER_TEXT_ENCODING': '0x27:0:0', 'PATH': '/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin', 'TASKCLUSTER_PROXY_URL': 'http://localhost:8080', 'PWD': '/Users/cltbld/tasks/task_1587530541/fetches/condprofile', 'MOZ_FETCHES_DIR': '/Users/cltbld/tasks/task_1587530541/fetches', 'MOZ_SCM_LEVEL': '3', 'MOZ_AUTOMATION': '1', 'XPC_FLAGS': '0x0', 'XPC_SERVICE_NAME': '0', 'SHLVL': '2', 'HOME': '/Users/cltbld', 'LOGNAME': 'cltbld', 'LC_CTYPE': 'UTF-8', 'SCCACHE_DISABLE': '1', '_': 'bin/python3', 'CONDPROF_RUNNER': '1'})
[task 2020-04-22T05:59:35.601Z] condprof INFO | Archives directory is /Users/cltbld/tasks/task_1587530541/archive
[task 2020-04-22T05:59:35.601Z] condprof INFO | Verifying Geckodriver binary presence
[task 2020-04-22T05:59:35.615Z] condprof INFO | Getting https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-macosx64/artifacts/public/condprof/changelog.json
[task 2020-04-22T05:59:35.630Z] condprof INFO | Getting headers at https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-macosx64/artifacts/public/condprof/changelog.json
[task 2020-04-22T05:59:35.717Z] condprof INFO | Redirected
[task 2020-04-22T05:59:35.717Z] condprof INFO | Getting headers at https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Vwv0hLuvQeS-WTtyxLjpkg/artifacts/public%2Fcondprof%2Fchangelog.json
[task 2020-04-22T05:59:41.618Z] condprof INFO | Redirected
[task 2020-04-22T05:59:41.618Z] condprof INFO | Getting headers at https://firefoxci.taskcluster-artifacts.net/Vwv0hLuvQeS-WTtyxLjpkg/0/public/condprof/changelog.json
[task 2020-04-22T05:59:42.286Z] condprof INFO | Response code is 200
[task 2020-04-22T05:59:42.288Z] condprof INFO | Downloading https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-macosx64/artifacts/public/condprof/changelog.json
[task 2020-04-22T06:00:26.293Z] Traceback (most recent call last):
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/connectionpool.py", line 421, in _make_request
[task 2020-04-22T06:00:26.294Z]     six.raise_from(e, None)
[task 2020-04-22T06:00:26.294Z]   File "<string>", line 3, in raise_from
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/connectionpool.py", line 416, in _make_request
[task 2020-04-22T06:00:26.294Z]     httplib_response = conn.getresponse()
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/client.py", line 1336, in getresponse
[task 2020-04-22T06:00:26.294Z]     response.begin()
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/client.py", line 306, in begin
[task 2020-04-22T06:00:26.294Z]     version, status, reason = self._read_status()
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/client.py", line 267, in _read_status
[task 2020-04-22T06:00:26.294Z]     line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/socket.py", line 589, in readinto
[task 2020-04-22T06:00:26.294Z]     return self._sock.recv_into(b)
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 1071, in recv_into
[task 2020-04-22T06:00:26.294Z]     return self.read(nbytes, buffer)
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/Cellar/python/3.7.4/Frameworks/Python.framework/Versions/3.7/lib/python3.7/ssl.py", line 929, in read
[task 2020-04-22T06:00:26.294Z]     return self._sslobj.read(len, buffer)
[task 2020-04-22T06:00:26.294Z] TimeoutError: [Errno 60] Operation timed out
[task 2020-04-22T06:00:26.294Z] 
[task 2020-04-22T06:00:26.294Z] During handling of the above exception, another exception occurred:
[task 2020-04-22T06:00:26.294Z] 
[task 2020-04-22T06:00:26.294Z] Traceback (most recent call last):
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/requests/adapters.py", line 449, in send
[task 2020-04-22T06:00:26.294Z]     timeout=timeout
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/connectionpool.py", line 720, in urlopen
[task 2020-04-22T06:00:26.294Z]     method, url, error=e, _pool=self, _stacktrace=sys.exc_info()[2]
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/util/retry.py", line 400, in increment
[task 2020-04-22T06:00:26.294Z]     raise six.reraise(type(error), error, _stacktrace)
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/packages/six.py", line 735, in reraise
[task 2020-04-22T06:00:26.294Z]     raise value
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/connectionpool.py", line 672, in urlopen
[task 2020-04-22T06:00:26.294Z]     chunked=chunked,
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/connectionpool.py", line 423, in _make_request
[task 2020-04-22T06:00:26.294Z]     self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
[task 2020-04-22T06:00:26.294Z]   File "/usr/local/lib/python3.7/site-packages/urllib3/connectionpool.py", line 348, in _raise_timeout
[task 2020-04-22T06:00:26.294Z]     self, url, "Read timed out. (read timeout=%s)" % timeout_value
[task 2020-04-22T06:00:26.294Z] urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='firefox-ci-tc.services.mozilla.com', port=443): Read timed out. (read timeout=30)
[task 2020-04-22T06:00:26.294Z] 
[task 2020-04-22T06:00:26.294Z] During handling of the above exception, another exception occurred:
[task 2020-04-22T06:00:26.294Z] 
[task 2020-04-22T06:00:26.294Z] Traceback (most recent call last):
[task 2020-04-22T06:00:26.294Z]   File "condprof/main.py", line 78, in <module>
[task 2020-04-22T06:00:26.295Z]     main()
[task 2020-04-22T06:00:26.295Z]   File "condprof/main.py", line 73, in main
[task 2020-04-22T06:00:26.295Z]     args.device_name,
[task 2020-04-22T06:00:26.295Z]   File "condprof/../condprof/runner.py", line 183, in run
[task 2020-04-22T06:00:26.295Z]     runner.prepare(scenario, customization)
[task 2020-04-22T06:00:26.295Z]   File "condprof/../condprof/runner.py", line 101, in prepare
[task 2020-04-22T06:00:26.295Z]     self.changelog = read_changelog(plat)
[task 2020-04-22T06:00:26.295Z]   File "condprof/../condprof/client.py", line 170, in read_changelog
[task 2020-04-22T06:00:26.295Z]     download_file(changelog_url, target=downloaded_changelog)
[task 2020-04-22T06:00:26.295Z]   File "condprof/../condprof/util.py", line 216, in download_file
[task 2020-04-22T06:00:26.295Z]     req = requests.get(url, stream=True, timeout=DOWNLOAD_TIMEOUT)
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/api.py", line 75, in get
[task 2020-04-22T06:00:26.295Z]     return request('get', url, params=params, **kwargs)
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/api.py", line 60, in request
[task 2020-04-22T06:00:26.295Z]     return session.request(method=method, url=url, **kwargs)
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 533, in request
[task 2020-04-22T06:00:26.295Z]     resp = self.send(prep, **send_kwargs)
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 668, in send
[task 2020-04-22T06:00:26.295Z]     history = [resp for resp in gen] if allow_redirects else []
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 668, in <listcomp>
[task 2020-04-22T06:00:26.295Z]     history = [resp for resp in gen] if allow_redirects else []
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 247, in resolve_redirects
[task 2020-04-22T06:00:26.295Z]     **adapter_kwargs
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/sessions.py", line 646, in send
[task 2020-04-22T06:00:26.295Z]     r = adapter.send(request, **kwargs)
[task 2020-04-22T06:00:26.295Z]   File "/usr/local/lib/python3.7/site-packages/requests/adapters.py", line 529, in send
[task 2020-04-22T06:00:26.295Z]     raise ReadTimeout(e, request=request)
[task 2020-04-22T06:00:26.295Z] requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='firefox-ci-tc.services.mozilla.com', port=443): Read timed out. (read timeout=30)
[fetches 2020-04-22T06:00:26.341Z] removing /Users/cltbld/tasks/task_1587530541/fetches
[fetches 2020-04-22T06:00:26.478Z] finished
[taskcluster 2020-04-22T06:00:26.488Z]    Exit Code: 1
[taskcluster 2020-04-22T06:00:26.488Z]    User Time: 15.331195s
[taskcluster 2020-04-22T06:00:26.488Z]  Kernel Time: 2.265528s
[taskcluster 2020-04-22T06:00:26.488Z]    Wall Time: 1m24.963295621s
[taskcluster 2020-04-22T06:00:26.488Z]       Result: FAILED
[taskcluster 2020-04-22T06:00:26.488Z] === Task Finished ===
[taskcluster 2020-04-22T06:00:26.488Z] Task Duration: 1m24.967004054s
[taskcluster:error] exit status 1

Adds retries for the changelog as well.

Pushed by tziade@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d5a56993b0be
retry on changelog downloads r=Bebe
Status: NEW → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla77
You need to log in before you can comment on or make changes to this bug.