[taskcluster 2024-05-21 20:20:02.254Z] Task ID: EskmcoDlRAKlimWZrwIkaQ
[taskcluster 2024-05-21 20:20:02.254Z] Worker ID: 2491745565006675702
[taskcluster 2024-05-21 20:20:02.254Z] Worker Group: us-west1-a
[taskcluster 2024-05-21 20:20:02.254Z] Worker Node Type: projects/887720501152/machineTypes/n2-standard-4
[taskcluster 2024-05-21 20:20:02.254Z] Worker Pool: scriptworker-1/b-linux-gcp
[taskcluster 2024-05-21 20:20:02.254Z] Worker Version: 38.0.5
[taskcluster 2024-05-21 20:20:02.254Z] Public IP: 34.105.112.196
[taskcluster 2024-05-21 20:20:02.254Z] Hostname: scriptworker-1-b-linux-gcp-zwr4-axxrtmxxyxrcmfxhw
[taskcluster 2024-05-21 20:20:02.254Z] using cache "scriptworker-level-1-checkouts-v3-7afeb851dd97df8f3607-albwS2faTC6SR_wVpaXZHA" -> /builds/worker/checkouts

[taskcluster 2024-05-21 20:20:02.627Z] Downloading artifact "public/image.tar.zst" from task ID: albwS2faTC6SR_wVpaXZHA.
[taskcluster 2024-05-21 20:20:03.706Z] Downloaded artifact successfully.
[taskcluster 2024-05-21 20:20:03.706Z] Downloaded 73.973 mb
[taskcluster 2024-05-21 20:20:03.706Z] Decompressing downloaded image
[taskcluster 2024-05-21 20:20:04.137Z] Loading docker image from downloaded archive.
[taskcluster 2024-05-21 20:20:07.092Z] Image 'public/image.tar.zst' from task 'albwS2faTC6SR_wVpaXZHA' loaded.  Using image ID sha256:27bc6849b0b67a91fff881051a7b94139cc6f5e17019f326c9950887fe43b6b1.
[taskcluster 2024-05-21 20:20:07.141Z] === Task Starting ===
[setup 2024-05-21T20:20:07.836Z] run-task started in /
[setup 2024-05-21T20:20:07.837Z] Invoked by command: --scriptworker-checkout=/builds/worker/checkouts/vcs/ --task-cwd /builds/worker/checkouts/vcs -- sh -lxce tox -e py39,check
[setup 2024-05-21T20:20:07.837Z] Python version: 3.9.18
[cache 2024-05-21T20:20:07.838Z] cache /builds/worker/checkouts is empty; writing requirements: gid=1000 uid=1000 version=1
[volume 2024-05-21T20:20:07.839Z] changing ownership of volume /builds/worker/.cache to 1000:1000
[volume 2024-05-21T20:20:07.839Z] volume /builds/worker/checkouts is a cache
[setup 2024-05-21T20:20:07.839Z] running as worker:worker
[vcs 2024-05-21T20:20:07.839Z] executing ['git', 'config', '--global', '--add', 'safe.directory', '/builds/worker/checkouts/vcs']
[vcs 2024-05-21T20:20:07.842Z] executing ['git', 'clone', 'https://github.com/mozilla-releng/scriptworker', '/builds/worker/checkouts/vcs']
[vcs 2024-05-21T20:20:07.844Z] Cloning into '/builds/worker/checkouts/vcs'...
[vcs 2024-05-21T20:20:08.577Z] executing ['git', 'fetch', '--no-tags', 'https://github.com/ahal/scriptworker', 'fix_verify_cot']
[vcs 2024-05-21T20:20:08.967Z] From https://github.com/ahal/scriptworker
[vcs 2024-05-21T20:20:08.967Z]  * branch            fix_verify_cot -> FETCH_HEAD
[vcs 2024-05-21T20:20:08.968Z] executing ['git', 'checkout', '-f', '-B', 'fix_verify_cot', 'adbb1b12cb1e17638326aae6ca58fe2ff976bd02']
[vcs 2024-05-21T20:20:09.044Z] Switched to a new branch 'fix_verify_cot'
[vcs 2024-05-21T20:20:09.044Z] cleaning git checkout...
[vcs 2024-05-21T20:20:09.044Z] executing ['git', 'clean', '-nxdff']
[vcs 2024-05-21T20:20:09.047Z] removing []
[vcs 2024-05-21T20:20:09.047Z] successfully cleaned git checkout!
[vcs 2024-05-21T20:20:09.049Z] TinderboxPrint:<a href='https://github.com/ahal/scriptworker/commit/adbb1b12cb1e17638326aae6ca58fe2ff976bd02' title='Built from scriptworker commit adbb1b12cb1e17638326aae6ca58fe2ff976bd02'>adbb1b12cb1e17638326aae6ca58fe2ff976bd02</a>
[task 2024-05-21T20:20:09.049Z] executing ['sh', '-lxce', 'tox -e py39,check']
[task 2024-05-21T20:20:09.050Z] + id -u
[task 2024-05-21T20:20:09.051Z] + [ 1000 -eq 0 ]
[task 2024-05-21T20:20:09.051Z] + PATH=/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games
[task 2024-05-21T20:20:09.051Z] + export PATH
[task 2024-05-21T20:20:09.051Z] + [ $  ]
[task 2024-05-21T20:20:09.051Z] + [  ]
[task 2024-05-21T20:20:09.051Z] + id -u
[task 2024-05-21T20:20:09.052Z] + [ 1000 -eq 0 ]
[task 2024-05-21T20:20:09.052Z] + PS1=$ 
[task 2024-05-21T20:20:09.052Z] + [ -d /etc/profile.d ]
[task 2024-05-21T20:20:09.052Z] + [ -r /etc/profile.d/*.sh ]
[task 2024-05-21T20:20:09.052Z] + unset i
[task 2024-05-21T20:20:09.052Z] + [ -n  ]
[task 2024-05-21T20:20:09.052Z] + [ -d /builds/worker/bin ]
[task 2024-05-21T20:20:09.053Z] + [ -d /builds/worker/.local/bin ]
[task 2024-05-21T20:20:09.053Z] + tox -e py39,check
[task 2024-05-21T20:20:09.639Z] .pkg: remove tox env folder /builds/worker/checkouts/vcs/.tox/.pkg
[task 2024-05-21T20:20:09.892Z] py39: install_deps> python -I -m pip install 'aiohttp>=3' asyncio_extras coveralls flake8 flake8_docstrings mock pydocstyle==3.0.0 pytest pytest-asyncio pytest-mock pytest-random-order virtualenv
[task 2024-05-21T20:20:17.382Z] .pkg: install_requires> python -I -m pip install 'setuptools>=40.8.0' wheel
[task 2024-05-21T20:20:18.394Z] .pkg: _optional_hooks> python /usr/local/lib/python3.9/site-packages/pyproject_api/_backend.py True setuptools.build_meta __legacy__
[task 2024-05-21T20:20:18.621Z] .pkg: get_requires_for_build_editable> python /usr/local/lib/python3.9/site-packages/pyproject_api/_backend.py True setuptools.build_meta __legacy__
[task 2024-05-21T20:20:18.782Z] .pkg: install_requires_for_build_editable> python -I -m pip install wheel
[task 2024-05-21T20:20:19.199Z] .pkg: build_editable> python /usr/local/lib/python3.9/site-packages/pyproject_api/_backend.py True setuptools.build_meta __legacy__
[task 2024-05-21T20:20:19.309Z] py39: install_package_deps> python -I -m pip install PyYAML 'aiohttp>=3' aiomemoizettl 'arrow>=1.0' 'cryptography>=2.6.1' dictdiffer github3.py 'immutabledict>=1.3.0' 'json-e>=2.5.0' jsonschema 'taskcluster>=40'
[task 2024-05-21T20:20:23.530Z] py39: install_package> python -I -m pip install --force-reinstall --no-deps /builds/worker/checkouts/vcs/.tox/.tmp/package/1/scriptworker-50.2.0-0.editable-py2.py3-none-any.whl
[task 2024-05-21T20:20:23.953Z] py39: commands[0]> coverage run --source=src/scriptworker --branch --rcfile tox.ini -m pytest tests
[task 2024-05-21T20:20:25.739Z] ============================= test session starts ==============================
[task 2024-05-21T20:20:25.739Z] platform linux -- Python 3.9.18, pytest-8.2.1, pluggy-1.5.0
[task 2024-05-21T20:20:25.739Z] cachedir: .tox/py39/.pytest_cache
[task 2024-05-21T20:20:25.739Z] Test order randomisation NOT enabled. Enable with --random-order or --random-order-bucket=<bucket_type>
[task 2024-05-21T20:20:25.739Z] rootdir: /builds/worker/checkouts/vcs
[task 2024-05-21T20:20:25.739Z] configfile: pyproject.toml
[task 2024-05-21T20:20:25.739Z] plugins: asyncio-0.23.7, random-order-1.1.1, mock-3.14.0
[task 2024-05-21T20:20:25.739Z] asyncio: mode=auto
[task 2024-05-21T20:20:25.739Z] collected 681 items
[task 2024-05-21T20:20:25.739Z] 
[task 2024-05-21T20:20:37.027Z] tests/test_artifacts.py .....................................            [  5%]
[task 2024-05-21T20:20:37.111Z] tests/test_client.py ..........................                          [  9%]
[task 2024-05-21T20:20:37.204Z] tests/test_config.py ....................................                [ 14%]
[task 2024-05-21T20:20:37.247Z] tests/test_context.py .............                                      [ 16%]
[task 2024-05-21T20:20:37.349Z] tests/test_cot_generate.py ......                                        [ 17%]
[task 2024-05-21T20:20:37.541Z] tests/test_cot_verify.py ............................................... [ 24%]
[task 2024-05-21T20:20:41.123Z] ........................................................................ [ 34%]
[task 2024-05-21T20:20:41.941Z] ........................................................................ [ 45%]
[task 2024-05-21T20:20:42.006Z] .............                                                            [ 47%]
[task 2024-05-21T20:20:42.021Z] tests/test_ed25519.py ........                                           [ 48%]
[task 2024-05-21T20:20:42.461Z] tests/test_github.py ................................................... [ 55%]
[task 2024-05-21T20:20:42.476Z] ...                                                                      [ 56%]
[task 2024-05-21T20:20:42.489Z] tests/test_integration.py ssssssssssss                                   [ 58%]
[task 2024-05-21T20:20:42.542Z] tests/test_log.py .........                                              [ 59%]
[task 2024-05-21T20:20:42.593Z] tests/test_production.py sssssssssssssss                                 [ 61%]
[task 2024-05-21T20:20:45.581Z] tests/test_task.py ..................................................... [ 69%]
[task 2024-05-21T20:20:52.913Z] ...........................................................              [ 78%]
[task 2024-05-21T20:20:55.932Z] tests/test_task_process.py ....                                          [ 78%]
[task 2024-05-21T20:20:56.557Z] tests/test_utils.py .................................................... [ 86%]
[task 2024-05-21T20:20:56.722Z] ...........................................................              [ 95%]
[task 2024-05-21T20:20:56.735Z] tests/test_version.py ..........                                         [ 96%]
[task 2024-05-21T20:20:59.110Z] tests/test_worker.py ........................                            [100%]
[task 2024-05-21T20:20:59.110Z] 
[task 2024-05-21T20:20:59.110Z] =============================== warnings summary ===============================
[task 2024-05-21T20:20:59.110Z] tests/conftest.py:81
[task 2024-05-21T20:20:59.110Z]   /builds/worker/checkouts/vcs/tests/conftest.py:81: PytestRemovedIn9Warning: Marks applied to fixtures have no effect
[task 2024-05-21T20:20:59.110Z]   See docs: https://docs.pytest.org/en/stable/deprecations.html#applying-a-mark-to-a-fixture-function
[task 2024-05-21T20:20:59.110Z]     async def fake_session():
[task 2024-05-21T20:20:59.110Z] 
[task 2024-05-21T20:20:59.110Z] tests/conftest.py:90
[task 2024-05-21T20:20:59.111Z]   /builds/worker/checkouts/vcs/tests/conftest.py:90: PytestRemovedIn9Warning: Marks applied to fixtures have no effect
[task 2024-05-21T20:20:59.111Z]   See docs: https://docs.pytest.org/en/stable/deprecations.html#applying-a-mark-to-a-fixture-function
[task 2024-05-21T20:20:59.111Z]     async def fake_session_500():
[task 2024-05-21T20:20:59.111Z] 
[task 2024-05-21T20:20:59.111Z] tests/conftest.py:99
[task 2024-05-21T20:20:59.111Z]   /builds/worker/checkouts/vcs/tests/conftest.py:99: PytestRemovedIn9Warning: Marks applied to fixtures have no effect
[task 2024-05-21T20:20:59.111Z]   See docs: https://docs.pytest.org/en/stable/deprecations.html#applying-a-mark-to-a-fixture-function
[task 2024-05-21T20:20:59.111Z]     async def fake_session_404():
[task 2024-05-21T20:20:59.111Z] 
[task 2024-05-21T20:20:59.111Z] tests/test_worker.py::test_mocker_run_tasks_caught_exception[run_task-ScriptWorkerException-5]
[task 2024-05-21T20:20:59.111Z] tests/test_worker.py::test_mocker_run_tasks_caught_exception[upload_artifacts-ClientError-7]
[task 2024-05-21T20:20:59.111Z] tests/test_worker.py::test_run_tasks_killed
[task 2024-05-21T20:20:59.111Z] tests/test_worker.py::test_run_tasks_cancel_claim_work
[task 2024-05-21T20:20:59.111Z] tests/test_worker.py::test_run_tasks_cancel_cot
[task 2024-05-21T20:20:59.111Z]   /usr/local/lib/python3.9/asyncio/base_events.py:672: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2024-05-21T20:20:59.111Z]     self._ready.clear()
[task 2024-05-21T20:20:59.111Z]   Enable tracemalloc to get traceback where the object was allocated.
[task 2024-05-21T20:20:59.111Z]   See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.
[task 2024-05-21T20:20:59.111Z] 
[task 2024-05-21T20:20:59.111Z] -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
[task 2024-05-21T20:20:59.111Z] ================= 654 passed, 27 skipped, 8 warnings in 34.40s =================
[task 2024-05-21T20:20:59.113Z] Task was destroyed but it is pending!
[task 2024-05-21T20:20:59.113Z] task: <Task cancelling name='Task-1110' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2024-05-21T20:20:59.114Z] /usr/local/lib/python3.9/asyncio/base_events.py:672: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2024-05-21T20:20:59.114Z]   self._ready.clear()
[task 2024-05-21T20:20:59.114Z] RuntimeWarning: Enable tracemalloc to get the object allocation traceback
[task 2024-05-21T20:20:59.114Z] Task was destroyed but it is pending!
[task 2024-05-21T20:20:59.114Z] task: <Task cancelling name='Task-1115' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2024-05-21T20:20:59.114Z] Task was destroyed but it is pending!
[task 2024-05-21T20:20:59.114Z] task: <Task cancelling name='Task-1121' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2024-05-21T20:20:59.160Z] Task was destroyed but it is pending!
[task 2024-05-21T20:20:59.160Z] task: <Task cancelling name='Task-1103' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2024-05-21T20:20:59.238Z] .pkg: _exit> python /usr/local/lib/python3.9/site-packages/pyproject_api/_backend.py True setuptools.build_meta __legacy__
[task 2024-05-21T20:20:59.397Z] py39: OK ✔ in 49.64 seconds
[task 2024-05-21T20:20:59.397Z] check: install_deps> python -I -m pip install black check-manifest flake8 'isort>=5'
[task 2024-05-21T20:21:02.461Z] check: commands[0]> black --check /builds/worker/checkouts/vcs
[task 2024-05-21T20:21:03.593Z] All done! ✨ 🍰 ✨
[task 2024-05-21T20:21:03.593Z] 44 files would be left unchanged.
[task 2024-05-21T20:21:03.615Z] check: commands[1]> isort --check --df /builds/worker/checkouts/vcs
[task 2024-05-21T20:21:03.903Z] Skipped 2 files
[task 2024-05-21T20:21:03.915Z] check: commands[2]> flake8 /builds/worker/checkouts/vcs
[task 2024-05-21T20:21:05.106Z] check: commands[3]> check-manifest -v /builds/worker/checkouts/vcs
[task 2024-05-21T20:21:06.288Z] listing source files under version control: 31 files and directories
[task 2024-05-21T20:21:06.288Z] building an sdist: scriptworker-50.2.0.tar.gz: 31 files and directories
[task 2024-05-21T20:21:06.288Z] copying source files to a temporary directory
[task 2024-05-21T20:21:06.288Z] building a clean sdist: scriptworker-50.2.0.tar.gz: 31 files and directories
[task 2024-05-21T20:21:06.288Z] lists of files in version control and sdist match
[task 2024-05-21T20:21:06.307Z]   py39: OK (49.64=setup[14.36]+cmd[35.28] seconds)
[task 2024-05-21T20:21:06.307Z]   check: OK (7.03=setup[3.18]+cmd[1.15,0.30,1.19,1.20] seconds)
[task 2024-05-21T20:21:06.307Z]   congratulations :) (56.94 seconds)
[taskcluster 2024-05-21 20:21:06.615Z] === Task Finished ===
[taskcluster 2024-05-21 20:21:06.615Z] Successful task run with exit code: 0 completed in 64.362 seconds