Closed Bug 1624794 Opened 4 years ago Closed 4 years ago

Mac signing scriptworkers hitting intermittent timeout during artifact upload

Categories

(Release Engineering :: Release Automation: Signing, defect)

Product:
Release Engineering
Component:
Release Automation: Signing
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: nthomas, Assigned: mozilla)

References

Details

Attachments

(2 files)

[scriptworker] catch TimeoutError on upload
55 bytes, text/x-github-pull-request
Details | Review
[scriptworker-scripts] scriptworker 32.2.1
63 bytes, text/x-github-pull-request
Details | Review

Don't know if this is scriptworker or taskcluster but we lost a lot of workers to this.

eg https://firefox-ci-tc.services.mozilla.com/tasks/Jfxx0Wh6R4-zBdYMLxiiJw/runs/0 but we don't see the error there, but in the log on the worker as it finishes the task:

...
2020-03-24T00:45:22     INFO - 2020-03-24 00:45:22,771 - iscript.mac - INFO - Done stapling notarization.
2020-03-24T00:45:22     INFO - exit code: 0
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/chain-of-trust.json.sig" is encoded with "None" and has mime/type "application/pgp-signature"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/chain-of-trust.json.sig" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/chain-of-trust.json" is encoded with "None" and has mime/type "application/json"
2020-03-24T00:45:25     INFO - "/builds/scriptworker/artifacts/public/chain-of-trust.json" can be gzip'd. Compressing...
2020-03-24T00:45:25     INFO - "/builds/scriptworker/artifacts/public/chain-of-trust.json" compressed
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/logs/chain_of_trust.log" is encoded with "None" and has mime/type "text/plain"
2020-03-24T00:45:25     INFO - "/builds/scriptworker/artifacts/public/logs/chain_of_trust.log" can be gzip'd. Compressing...
2020-03-24T00:45:25     INFO - "/builds/scriptworker/artifacts/public/logs/chain_of_trust.log" compressed
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/logs/live_backing.log" is encoded with "None" and has mime/type "text/plain"
2020-03-24T00:45:25     INFO - "/builds/scriptworker/artifacts/public/logs/live_backing.log" can be gzip'd. Compressing...
2020-03-24T00:45:25     INFO - "/builds/scriptworker/artifacts/public/logs/live_backing.log" compressed
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/el/target.tar.gz" is encoded with "None" and has mime/type "application/x-tar"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/el/target.tar.gz" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/el/target.pkg" is encoded with "None" and has mime/type "application/octet-stream"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/el/target.pkg" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-GB/target.tar.gz" is encoded with "None" and has mime/type "application/x-tar"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-GB/target.tar.gz" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-GB/target.pkg" is encoded with "None" and has mime/type "application/octet-stream"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-GB/target.pkg" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-CA/target.tar.gz" is encoded with "None" and has mime/type "application/x-tar"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-CA/target.tar.gz" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-CA/target.pkg" is encoded with "None" and has mime/type "application/octet-stream"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/en-CA/target.pkg" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/eo/target.tar.gz" is encoded with "None" and has mime/type "application/x-tar"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/eo/target.tar.gz" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/eo/target.pkg" is encoded with "None" and has mime/type "application/octet-stream"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/eo/target.pkg" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/dsb/target.tar.gz" is encoded with "None" and has mime/type "application/x-tar"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/dsb/target.tar.gz" is not supported for compression.
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/dsb/target.pkg" is encoded with "None" and has mime/type "application/octet-stream"
2020-03-24T00:45:25    DEBUG - "/builds/scriptworker/artifacts/public/build/dsb/target.pkg" is not supported for compression.
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/dsb/target.tar.gz to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/dsb/target.tar.gz?<snip>...
2020-03-24T00:45:25    DEBUG - application/x-tar None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/eo/target.tar.gz to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/eo/target.tar.gz?<snip>...
2020-03-24T00:45:25    DEBUG - application/x-tar None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/en-CA/target.pkg to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/en-CA/target.pkg?<snip>...
2020-03-24T00:45:25    DEBUG - application/octet-stream None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/en-GB/target.tar.gz to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/en-GB/target.tar.gz?<snip>...
2020-03-24T00:45:25    DEBUG - application/x-tar None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/en-CA/target.tar.gz to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/en-CA/target.tar.gz?<snip>...
2020-03-24T00:45:25    DEBUG - application/x-tar None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/el/target.tar.gz to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/el/target.tar.gz?<snip>...
2020-03-24T00:45:25    DEBUG - application/x-tar None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/en-GB/target.pkg to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/en-GB/target.pkg?<snip>...
2020-03-24T00:45:25    DEBUG - application/octet-stream None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/chain-of-trust.json to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/chain-of-trust.json?<snip>...
2020-03-24T00:45:25    DEBUG - application/json gzip
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/el/target.pkg to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/el/target.pkg?<snip>...
2020-03-24T00:45:25    DEBUG - application/octet-stream None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/chain-of-trust.json.sig to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/chain-of-trust.json.sig?<snip>...
2020-03-24T00:45:25    DEBUG - application/pgp-signature None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/dsb/target.pkg to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/dsb/target.pkg?<snip>...
2020-03-24T00:45:25    DEBUG - application/octet-stream None
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/logs/chain_of_trust.log to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/logs/chain_of_trust.log?<snip>...
2020-03-24T00:45:25    DEBUG - text/plain gzip
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/logs/live_backing.log to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/logs/live_backing.log?<snip>...
2020-03-24T00:45:25    DEBUG - text/plain gzip
2020-03-24T00:45:25     INFO - create_artifact /builds/scriptworker/artifacts/public/chain-of-trust.json.sig: 200
2020-03-24T00:45:25     INFO -
2020-03-24T00:45:25     INFO - uploading /builds/scriptworker/artifacts/public/build/eo/target.pkg to https://firefoxcitc-public-artifacts.s3.us-west-2.amazonaws.com/Jfxx0Wh6R4-zBdYMLxiiJw/0/public/build/eo/target.pkg?<snip>...
2020-03-24T00:45:25    DEBUG - application/octet-stream None
2020-03-24T00:45:25     INFO - create_artifact /builds/scriptworker/artifacts/public/logs/live_backing.log: 200
2020-03-24T00:45:25     INFO -
2020-03-24T00:45:25     INFO - create_artifact /builds/scriptworker/artifacts/public/chain-of-trust.json: 200
2020-03-24T00:45:25     INFO -
2020-03-24T00:45:26     INFO - create_artifact /builds/scriptworker/artifacts/public/logs/chain_of_trust.log: 200
2020-03-24T00:45:26     INFO -
2020-03-24T00:45:29     INFO - create_artifact /builds/scriptworker/artifacts/public/build/eo/target.tar.gz: 200
2020-03-24T00:45:29     INFO -
2020-03-24T00:45:29     INFO - create_artifact /builds/scriptworker/artifacts/public/build/el/target.tar.gz: 200
2020-03-24T00:45:29     INFO -
2020-03-24T00:45:38     INFO - create_artifact /builds/scriptworker/artifacts/public/build/en-CA/target.pkg: 200
2020-03-24T00:45:38     INFO -
2020-03-24T00:45:40     INFO - create_artifact /builds/scriptworker/artifacts/public/build/eo/target.pkg: 200
2020-03-24T00:45:40     INFO -
2020-03-24T00:45:40     INFO - create_artifact /builds/scriptworker/artifacts/public/build/dsb/target.tar.gz: 200
2020-03-24T00:45:40     INFO -
2020-03-24T00:45:40     INFO - create_artifact /builds/scriptworker/artifacts/public/build/en-GB/target.tar.gz: 200
2020-03-24T00:45:40     INFO -
2020-03-24T00:45:40     INFO - create_artifact /builds/scriptworker/artifacts/public/build/en-GB/target.pkg: 200
2020-03-24T00:45:40     INFO -
2020-03-24T00:45:42     INFO - create_artifact /builds/scriptworker/artifacts/public/build/dsb/target.pkg: 200
2020-03-24T00:45:42     INFO -
2020-03-24T00:45:42     INFO - create_artifact /builds/scriptworker/artifacts/public/build/el/target.pkg: 200
2020-03-24T00:45:42     INFO -
2020-03-24T00:49:22    DEBUG - Reclaiming task...
2020-03-24T00:49:22    DEBUG - Reclaim task response:
{'credentials': '{********}',
 'runId': 0,
 'status': {'deadline': '2020-03-24T22:02:41.716Z',
            'expires': '2021-03-23T22:02:41.716Z',
            'provisionerId': 'scriptworker-prov-v1',
            'retriesLeft': 5,
            'runs': [{'reasonCreated': 'scheduled',
                      'runId': 0,
                      'scheduled': '2020-03-24T00:44:11.215Z',
                      'started': '2020-03-24T00:44:22.178Z',
                      'state': 'running',
                      'takenUntil': '2020-03-24T01:09:22.511Z',
                      'workerGroup': 'signing-mac-v1',
                      'workerId': 'mac-v3-signing3'}],
            'schedulerId': 'gecko-level-3',
            'state': 'running',
            'taskGroupId': 'eED2CtXbToaPqIuIsIr9Zg',
            'taskId': 'Jfxx0Wh6R4-zBdYMLxiiJw',
            'workerType': 'signing-mac-v1'},
 'takenUntil': '2020-03-24T01:09:22.511Z',
 'workerGroup': 'signing-mac-v1',
 'workerId': 'mac-v3-signing3'}
2020-03-24T00:49:22    DEBUG - waiting 300 seconds before reclaiming...
2020-03-24T00:50:25    ERROR - SCRIPTWORKER_UNEXPECTED_EXCEPTION upload
Traceback (most recent call last):
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/worker.py", line 89, in do_upload
    await upload_artifacts(context, files)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/artifacts.py", line 68, in upload_artifacts
    await raise_future_exceptions(tasks)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/utils.py", line 398, in raise_future_exceptions
    succeeded_results, _ = await _process_future_exceptions(tasks, raise_at_first_error=True)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/utils.py", line 432, in _process_future_exceptions
    raise exc
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/artifacts.py", line 132, in retry_create_artifact
    await retry_async(create_artifact, retry_exceptions=(ScriptWorkerRetryException, aiohttp.ClientError), args=args, kwargs=kwargs)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/utils.py", line 259, in retry_async
    return await func(*args, **kwargs)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/artifacts.py", line 173, in create_artifact
    compress=False,
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/client.py", line 995, in __aenter__
    self._resp = await self._coro
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/client.py", line 487, in _request
    await resp.start(conn)
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/client_reqrep.py", line 857, in start
    self._continue = None
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/helpers.py", line 585, in __exit__
    raise asyncio.TimeoutError from None
concurrent.futures._base.TimeoutError
2020-03-24T00:50:26 CRITICAL - Fatal exception
Traceback (most recent call last):
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/worker.py", line 254, in main
    context.event_loop.run_until_complete(async_main(context, credentials))
  File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/worker.py", line 216, in async_main
    await run_tasks(context)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/worker.py", line 198, in run_tasks
    status = await running_tasks.invoke(context)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/worker.py", line 142, in invoke
    status = worst_level(status, await do_upload(context, artifacts_paths))
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/worker.py", line 89, in do_upload
    await upload_artifacts(context, files)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/artifacts.py", line 68, in upload_artifacts
    await raise_future_exceptions(tasks)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/utils.py", line 398, in raise_future_exceptions
    succeeded_results, _ = await _process_future_exceptions(tasks, raise_at_first_error=True)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/utils.py", line 432, in _process_future_exceptions
    raise exc
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/artifacts.py", line 132, in retry_create_artifact
    await retry_async(create_artifact, retry_exceptions=(ScriptWorkerRetryException, aiohttp.ClientError), args=args, kwargs=kwargs)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/utils.py", line 259, in retry_async
    return await func(*args, **kwargs)
  File "/builds/scriptworker/lib/python3.7/site-packages/scriptworker/artifacts.py", line 173, in create_artifact
    compress=False,
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/client.py", line 995, in __aenter__
    self._resp = await self._coro
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/client.py", line 487, in _request
    await resp.start(conn)
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/client_reqrep.py", line 857, in start
    self._continue = None
  File "/builds/scriptworker/lib/python3.7/site-packages/aiohttp-4.0.0a0-py3.7-macosx-10.9-x86_64.egg/aiohttp/helpers.py", line 585, in __exit__
    raise asyncio.TimeoutError from None
concurrent.futures._base.TimeoutError

aki, does this remind you of anything ?

Flags: needinfo?(aki)
Summary: Mac signing scriptworkers hitting intermittent timeout during artifact timeout → Mac signing scriptworkers hitting intermittent timeout during artifact upload

2020-03-19T22:06:29 was the earliest instance I saw of this, but it affected all the workers across the days since then.

I copied the above log to a file foo, then

grep '200$' foo | sed -e 's/.*create_artifact.*public/public/' | sed -e 's/: 200//' | sort > done
grep uploading foo | sed -e 's/ to .*//' | sed -e 's/.*public/public/' | sort > try
diff try done

gives me public/build/en-CA/target.tar.gz.

This looks like a scriptworker bug: we should be failing out of the task, but the scriptworker should still run.

Flags: needinfo?(aki)
Assignee: nobody → aki
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
See Also: → 1620262
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: