[taskcluster 2026-05-20T20:00:54.991Z] Worker Type (scriptworker-1/images) settings:
[taskcluster 2026-05-20T20:00:54.991Z]   {
[taskcluster 2026-05-20T20:00:54.991Z]     "generic-worker": {
[taskcluster 2026-05-20T20:00:54.991Z]       "config": {
[taskcluster 2026-05-20T20:00:54.991Z]         "headlessTasks": true
[taskcluster 2026-05-20T20:00:54.991Z]       },
[taskcluster 2026-05-20T20:00:54.991Z]       "engine": "multiuser",
[taskcluster 2026-05-20T20:00:54.991Z]       "go-arch": "amd64",
[taskcluster 2026-05-20T20:00:54.991Z]       "go-os": "linux",
[taskcluster 2026-05-20T20:00:54.991Z]       "go-version": "go1.26.2",
[taskcluster 2026-05-20T20:00:54.991Z]       "release": "https://github.com/taskcluster/taskcluster/releases/tag/v99.2.1",
[taskcluster 2026-05-20T20:00:54.991Z]       "revision": "ddb9ce7efdb98ae2d0917b69778e9f3cd125e07f",
[taskcluster 2026-05-20T20:00:54.991Z]       "source": "https://github.com/taskcluster/taskcluster/commits/ddb9ce7efdb98ae2d0917b69778e9f3cd125e07f",
[taskcluster 2026-05-20T20:00:54.991Z]       "version": "99.2.1"
[taskcluster 2026-05-20T20:00:54.991Z]     },
[taskcluster 2026-05-20T20:00:54.991Z]     "image": "projects/taskcluster-imaging/global/images/gw-fxci-gcp-l1-2404-amd64-headless-googlecompute-2026-05-04",
[taskcluster 2026-05-20T20:00:54.991Z]     "instance-id": "6151011066372664396",
[taskcluster 2026-05-20T20:00:54.991Z]     "instance-type": "projects/887720501152/machineTypes/c2-standard-4",
[taskcluster 2026-05-20T20:00:54.991Z]     "local-ipv4": "10.128.2.116",
[taskcluster 2026-05-20T20:00:54.991Z]     "project-id": "fxci-production-level1-workers",
[taskcluster 2026-05-20T20:00:54.991Z]     "public-hostname": "scriptworker-1-images-k4pnijuiqbs-t63dd4zjcw.c.fxci-production-level1-workers.internal",
[taskcluster 2026-05-20T20:00:54.991Z]     "public-ipv4": "34.10.110.212",
[taskcluster 2026-05-20T20:00:54.991Z]     "region": "us-central1",
[taskcluster 2026-05-20T20:00:54.991Z]     "zone": "us-central1-b"
[taskcluster 2026-05-20T20:00:54.991Z]   }
[taskcluster 2026-05-20T20:00:54.991Z] Task ID: MCVyCPN4Sby-GfK-gHEQdw
[taskcluster 2026-05-20T20:00:54.991Z] === Task Starting ===
[taskcluster 2026-05-20T20:00:56.018Z] [mounts] No existing writable directory cache 'scriptworker-level-1-uv-v3-5ddaa3ce44d7548e0d3c-OB_dsMysRHqOkcW64od4xg' - creating /home/generic-worker/caches/Z4Ory1w1TwSjwUkRpNb_mA
[taskcluster 2026-05-20T20:00:56.018Z] [mounts] Creating directory /home/task_177930725408634/cache0
[taskcluster 2026-05-20T20:00:56.029Z] [mounts] Successfully mounted writable directory cache '/home/task_177930725408634/cache0'
[taskcluster 2026-05-20T20:00:56.029Z] [mounts] No existing writable directory cache 'scriptworker-level-1-checkouts-v3-5ddaa3ce44d7548e0d3c-OB_dsMysRHqOkcW64od4xg' - creating /home/generic-worker/caches/XTSXoOp5QOmmDZQsBqupuA
[taskcluster 2026-05-20T20:00:56.029Z] [mounts] Creating directory /home/task_177930725408634/cache1
[taskcluster 2026-05-20T20:00:56.040Z] [mounts] Successfully mounted writable directory cache '/home/task_177930725408634/cache1'
[taskcluster 2026-05-20T20:00:56.040Z] [mounts] Downloading task OB_dsMysRHqOkcW64od4xg artifact public/image.tar.zst to /home/generic-worker/downloads/aWJ4gcZ5TxesMWA6tGxlXw
[taskcluster 2026-05-20T20:00:58.021Z] [mounts] Downloaded 100352544 bytes with SHA256 3519505fc005dbf64f268410c89c99655fc098e832279b7391c7cd11c142c0ce from task OB_dsMysRHqOkcW64od4xg artifact public/image.tar.zst to /home/generic-worker/downloads/aWJ4gcZ5TxesMWA6tGxlXw
[taskcluster:warn 2026-05-20T20:00:58.021Z] [mounts] Download /home/generic-worker/downloads/aWJ4gcZ5TxesMWA6tGxlXw of task OB_dsMysRHqOkcW64od4xg artifact public/image.tar.zst has SHA256 3519505fc005dbf64f268410c89c99655fc098e832279b7391c7cd11c142c0ce but task payload does not declare a required value, so content authenticity cannot be verified
[taskcluster 2026-05-20T20:00:58.021Z] [mounts] File mount "dockerimage" handled by registered handler (cache: /home/generic-worker/downloads/aWJ4gcZ5TxesMWA6tGxlXw, SHA256: 3519505fc005dbf64f268410c89c99655fc098e832279b7391c7cd11c142c0ce)
[taskcluster 2026-05-20T20:00:58.021Z] [d2g] Loading docker image
[taskcluster 2026-05-20T20:01:02.126Z] [d2g] Loaded docker image "python3.13:latest"
[taskcluster 2026-05-20T20:01:02.126Z] Executing command 0: docker run -t --name taskcontainer_DGuz_2s2T2qy1m8igZ_szg --memory-swap -1 --pids-limit -1 --pull=never --log-driver=none '--add-host=localhost.localdomain:127.0.0.1' -v '/home/task_177930725408634/cache0:/builds/worker/.task-cache/uv' -v /home/task_177930725408634/cache1:/builds/worker/checkouts --add-host=taskcluster:host-gateway --env-file 'env.list' 5c485d2b3b61a6dc8aa3162e7f2c79c59e6b410821694642b0429cdb5ed96989 /usr/local/bin/run-task --scriptworker-checkout=/builds/worker/checkouts/vcs/ --task-cwd /builds/worker/checkouts/vcs -- sh -lxce 'uv run tox -e py313'
[setup 2026-05-20T20:01:03.840+00:00] run-task started in /
[setup 2026-05-20T20:01:03.840+00:00] Invoked by command: --scriptworker-checkout=/builds/worker/checkouts/vcs/ --task-cwd /builds/worker/checkouts/vcs -- sh -lxce uv run tox -e py313
[setup 2026-05-20T20:01:03.840+00:00] Python version: 3.13.10
[setup 2026-05-20T20:01:03.840+00:00] Subprocess python version: 
cpython-3.13.10-linux-x86_64-gnu    /usr/local/bin/python3.13
cpython-3.13.10-linux-x86_64-gnu    /usr/local/bin/python3 -> python3.13
cpython-3.13.10-linux-x86_64-gnu    /usr/local/bin/python -> python3
[cache 2026-05-20T20:01:04.018+00:00] cache /builds/worker/.task-cache/uv is empty; writing requirements: gid=1000 uid=1000 version=1
[cache 2026-05-20T20:01:04.018+00:00] cache /builds/worker/checkouts is empty; writing requirements: gid=1000 uid=1000 version=1
[volume 2026-05-20T20:01:04.018+00:00] volume /builds/worker/.task-cache/uv is a cache
[volume 2026-05-20T20:01:04.018+00:00] volume /builds/worker/checkouts is a cache
[setup 2026-05-20T20:01:04.018+00:00] running as worker:worker
[vcs 2026-05-20T20:01:04.018+00:00] executing ['git', 'config', '--global', '--add', 'safe.directory', '/builds/worker/checkouts/vcs']
[vcs 2026-05-20T20:01:04.025+00:00] executing ['git', 'clone', 'https://github.com/mozilla-releng/scriptworker', '/builds/worker/checkouts/vcs']
[vcs 2026-05-20T20:01:04.026+00:00] Cloning into '/builds/worker/checkouts/vcs'...
[vcs 2026-05-20T20:01:05.473+00:00] executing ['git', 'fetch', '--tags', '--force', 'https://github.com/mozilla-releng/scriptworker', 'hneiva/cot-logs']
[vcs 2026-05-20T20:01:05.799+00:00] From https://github.com/mozilla-releng/scriptworker
[vcs 2026-05-20T20:01:05.799+00:00]  * branch            hneiva/cot-logs -> FETCH_HEAD
[vcs 2026-05-20T20:01:05.809+00:00] executing ['git', 'checkout', '-f', '-B', 'hneiva/cot-logs', '3768e775dcc5861ace3b22113d4f035b0014d770']
[vcs 2026-05-20T20:01:05.881+00:00] Switched to a new branch 'hneiva/cot-logs'
[vcs 2026-05-20T20:01:05.882+00:00] cleaning git checkout...
[vcs 2026-05-20T20:01:05.882+00:00] executing ['git', 'clean', '-nxdff']
[vcs 2026-05-20T20:01:05.884+00:00] removing []
[vcs 2026-05-20T20:01:05.884+00:00] successfully cleaned git checkout!
[vcs 2026-05-20T20:01:05.885+00:00] TinderboxPrint:<a href='https://github.com/mozilla-releng/scriptworker/commit/3768e775dcc5861ace3b22113d4f035b0014d770' title='Built from scriptworker commit 3768e775dcc5861ace3b22113d4f035b0014d770'>3768e775dcc5861ace3b22113d4f035b0014d770</a>
[setup 2026-05-20T20:01:05.885+00:00] UV_CACHE_DIR is /builds/worker/.task-cache/uv
[task 2026-05-20T20:01:05.885+00:00] executing ['sh', '-lxce', 'uv run tox -e py313']
[task 2026-05-20T20:01:05.886+00:00] + id -u
[task 2026-05-20T20:01:05.887+00:00] + [ 1000 -eq 0 ]
[task 2026-05-20T20:01:05.887+00:00] + PATH=/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games
[task 2026-05-20T20:01:05.887+00:00] + export PATH
[task 2026-05-20T20:01:05.887+00:00] + [ $  ]
[task 2026-05-20T20:01:05.887+00:00] + [  ]
[task 2026-05-20T20:01:05.887+00:00] + id -u
[task 2026-05-20T20:01:05.888+00:00] + [ 1000 -eq 0 ]
[task 2026-05-20T20:01:05.888+00:00] + PS1=$ 
[task 2026-05-20T20:01:05.888+00:00] + [ -d /etc/profile.d ]
[task 2026-05-20T20:01:05.888+00:00] + [ -r /etc/profile.d/*.sh ]
[task 2026-05-20T20:01:05.888+00:00] + unset i
[task 2026-05-20T20:01:05.888+00:00] + uv run tox -e py313
[task 2026-05-20T20:01:05.968+00:00] Using CPython 3.13.10 interpreter at: /usr/local/bin/python3
[task 2026-05-20T20:01:05.968+00:00] Creating virtual environment at: .venv
[task 2026-05-20T20:01:06.601+00:00]    Building scriptworker @ file:///builds/worker/checkouts/vcs
[task 2026-05-20T20:01:06.661+00:00] Downloading pygments (1.2MiB)
[task 2026-05-20T20:01:06.663+00:00] Downloading ruff (10.9MiB)
[task 2026-05-20T20:01:06.663+00:00] Downloading uv (23.3MiB)
[task 2026-05-20T20:01:06.664+00:00] Downloading ast-serialize (1.2MiB)
[task 2026-05-20T20:01:06.665+00:00] Downloading aiohttp (1.7MiB)
[task 2026-05-20T20:01:06.666+00:00] Downloading virtualenv (7.2MiB)
[task 2026-05-20T20:01:06.668+00:00] Downloading cryptography (4.5MiB)
[task 2026-05-20T20:01:06.670+00:00] Downloading mypy (14.3MiB)
[task 2026-05-20T20:01:07.131+00:00]  Downloaded ast-serialize
[task 2026-05-20T20:01:07.656+00:00]  Downloaded ruff
[task 2026-05-20T20:01:07.672+00:00]  Downloaded virtualenv
[task 2026-05-20T20:01:07.809+00:00]  Downloaded aiohttp
[task 2026-05-20T20:01:07.817+00:00]  Downloaded uv
[task 2026-05-20T20:01:07.838+00:00]  Downloaded cryptography
[task 2026-05-20T20:01:07.890+00:00]  Downloaded pygments
[task 2026-05-20T20:01:08.086+00:00]  Downloaded mypy
[task 2026-05-20T20:01:08.091+00:00]       Built scriptworker @ file:///builds/worker/checkouts/vcs
[task 2026-05-20T20:01:08.094+00:00] warning: Failed to hardlink files; falling back to full copy. This may lead to degraded performance.
[task 2026-05-20T20:01:08.094+00:00]          If the cache and target directories are on different filesystems, hardlinking may not be supported.
[task 2026-05-20T20:01:08.094+00:00]          If this is intentional, set `export UV_LINK_MODE=copy` or use `--link-mode=copy` to suppress this warning.
[task 2026-05-20T20:01:08.241+00:00] Installed 100 packages in 149ms
[task 2026-05-20T20:01:08.881+00:00] py313: venv> .venv/bin/uv venv -p cpython3.13 --allow-existing '--prompt=vcs[py313]' --python-preference system /builds/worker/checkouts/vcs/.tox/py313
[task 2026-05-20T20:01:09.076+00:00] .pkg: venv> .venv/bin/uv venv -p /builds/worker/checkouts/vcs/.venv/bin/python --allow-existing '--prompt=vcs[.pkg]' --python-preference system /builds/worker/checkouts/vcs/.tox/.pkg
[task 2026-05-20T20:01:09.085+00:00] .pkg: install_requires> .venv/bin/uv pip install hatchling
[task 2026-05-20T20:01:09.499+00:00] .pkg: _optional_hooks> python /builds/worker/checkouts/vcs/.venv/lib/python3.13/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-05-20T20:01:09.542+00:00] .pkg: get_requires_for_build_editable> python /builds/worker/checkouts/vcs/.venv/lib/python3.13/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-05-20T20:01:09.652+00:00] .pkg: install_requires_for_build_editable> .venv/bin/uv pip install 'editables~=0.3'
[task 2026-05-20T20:01:09.795+00:00] .pkg: build_editable> python /builds/worker/checkouts/vcs/.venv/lib/python3.13/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-05-20T20:01:09.889+00:00] py313: install_package_deps> .venv/bin/uv pip install PyYAML 'aiohttp>=3' 'arrow>=1.0' 'cryptography>=2.6.1' dictdiffer github3.py 'immutabledict>=1.3.0' 'json-e>=2.5.0' 'jsonschema[format-nongpl]' taskcluster-taskgraph 'taskcluster>=40'
[task 2026-05-20T20:01:10.977+00:00] py313: install_package> .venv/bin/uv pip install --reinstall --no-deps scriptworker@/builds/worker/checkouts/vcs/.tox/.tmp/package/1/scriptworker-63.0.1-py3-none-any.whl
[task 2026-05-20T20:01:11.039+00:00] py313: commands[0]> coverage run --source=src/scriptworker --branch --rcfile tox.ini -m pytest tests
[task 2026-05-20T20:01:16.824+00:00] ============================= test session starts ==============================
[task 2026-05-20T20:01:16.824+00:00] platform linux -- Python 3.13.10, pytest-9.0.3, pluggy-1.6.0
[task 2026-05-20T20:01:16.824+00:00] cachedir: .tox/py313/.pytest_cache
[task 2026-05-20T20:01:16.824+00:00] Test order randomisation NOT enabled. Enable with --random-order or --random-order-bucket=<bucket_type>
[task 2026-05-20T20:01:16.824+00:00] rootdir: /builds/worker/checkouts/vcs
[task 2026-05-20T20:01:16.824+00:00] configfile: pyproject.toml (WARNING: ignoring pytest config in tox.ini!)
[task 2026-05-20T20:01:16.824+00:00] plugins: random-order-1.2.0, asyncio-1.3.0, mock-3.15.1
[task 2026-05-20T20:01:16.824+00:00] asyncio: mode=Mode.AUTO, debug=False, asyncio_default_fixture_loop_scope=None, asyncio_default_test_loop_scope=function
[task 2026-05-20T20:01:16.824+00:00] collected 695 items
[task 2026-05-20T20:01:16.824+00:00] 
[task 2026-05-20T20:01:16.975+00:00] tests/test_artifacts.py ..........................................       [  6%]
[task 2026-05-20T20:01:17.077+00:00] tests/test_client.py .............................                       [ 10%]
[task 2026-05-20T20:01:17.185+00:00] tests/test_config.py ....................................                [ 15%]
[task 2026-05-20T20:01:17.229+00:00] tests/test_context.py .............                                      [ 17%]
[task 2026-05-20T20:01:17.289+00:00] tests/test_cot_generate.py ......                                        [ 18%]
[task 2026-05-20T20:01:17.511+00:00] tests/test_cot_verify.py ............................................... [ 24%]
[task 2026-05-20T20:01:20.561+00:00] ........................................................................ [ 35%]
[task 2026-05-20T20:01:21.466+00:00] ........................................................................ [ 45%]
[task 2026-05-20T20:01:21.589+00:00] .....................                                                    [ 48%]
[task 2026-05-20T20:01:21.606+00:00] tests/test_ed25519.py ........                                           [ 49%]
[task 2026-05-20T20:01:22.016+00:00] tests/test_github.py ................................................... [ 57%]
[task 2026-05-20T20:01:22.036+00:00] ...                                                                      [ 57%]
[task 2026-05-20T20:01:22.050+00:00] tests/test_integration.py ssssssssssss                                   [ 59%]
[task 2026-05-20T20:01:22.118+00:00] tests/test_log.py ...........                                            [ 60%]
[task 2026-05-20T20:01:22.130+00:00] tests/test_production.py sssssssssss                                     [ 62%]
[task 2026-05-20T20:01:24.545+00:00] tests/test_task.py ..................................................... [ 70%]
[task 2026-05-20T20:01:31.970+00:00] ...............................................................          [ 79%]
[task 2026-05-20T20:01:34.989+00:00] tests/test_task_process.py ....                                          [ 79%]
[task 2026-05-20T20:01:35.632+00:00] tests/test_utils.py .................................................... [ 87%]
[task 2026-05-20T20:01:35.881+00:00] ..............................................................           [ 96%]
[task 2026-05-20T20:01:38.387+00:00] tests/test_worker.py ................./builds/worker/checkouts/vcs/.venv/lib/python3.13/site-packages/_pytest/unraisableexception.py:33: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2026-05-20T20:01:38.387+00:00]   gc.collect()
[task 2026-05-20T20:01:38.387+00:00] RuntimeWarning: Enable tracemalloc to get the object allocation traceback
[task 2026-05-20T20:01:38.387+00:00] Task was destroyed but it is pending!
[task 2026-05-20T20:01:38.387+00:00] task: <Task cancelling name='Task-1980' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-05-20T20:01:38.387+00:00] Task was destroyed but it is pending!
[task 2026-05-20T20:01:38.387+00:00] task: <Task cancelling name='Task-1913' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-05-20T20:01:38.388+00:00] /usr/local/lib/python3.13/asyncio/base_events.py:750: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2026-05-20T20:01:38.388+00:00]   self._ready.clear()
[task 2026-05-20T20:01:38.388+00:00] RuntimeWarning: Enable tracemalloc to get the object allocation traceback
[task 2026-05-20T20:01:38.388+00:00] Task was destroyed but it is pending!
[task 2026-05-20T20:01:38.388+00:00] task: <Task cancelling name='Task-1965' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-05-20T20:01:38.597+00:00] ..........                         [100%]
[task 2026-05-20T20:01:38.598+00:00] 
[task 2026-05-20T20:01:38.598+00:00] =============================== warnings summary ===============================
[task 2026-05-20T20:01:38.598+00:00] tests/test_worker.py::test_run_tasks_timeout
[task 2026-05-20T20:01:38.598+00:00] tests/test_worker.py::test_run_tasks_cancel_run_tasks
[task 2026-05-20T20:01:38.598+00:00] tests/test_worker.py::test_run_tasks_cancel_right_before_proc_created
[task 2026-05-20T20:01:38.598+00:00]   /usr/local/lib/python3.13/asyncio/base_events.py:750: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2026-05-20T20:01:38.598+00:00]     self._ready.clear()
[task 2026-05-20T20:01:38.598+00:00]   Enable tracemalloc to get traceback where the object was allocated.
[task 2026-05-20T20:01:38.598+00:00]   See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.
[task 2026-05-20T20:01:38.598+00:00] 
[task 2026-05-20T20:01:38.598+00:00] -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
[task 2026-05-20T20:01:38.598+00:00] ================= 672 passed, 23 skipped, 3 warnings in 25.55s =================
[task 2026-05-20T20:01:38.886+00:00] .pkg: _exit> python /builds/worker/checkouts/vcs/.venv/lib/python3.13/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-05-20T20:01:38.924+00:00]   py313: OK (30.05=setup[2.20]+cmd[27.85] seconds)
[task 2026-05-20T20:01:38.924+00:00]   congratulations :) (30.12 seconds)
[taskcluster 2026-05-20T20:01:39.481Z]                        Exit Code: 0
[taskcluster 2026-05-20T20:01:39.481Z]                        User Time: 16.64ms
[taskcluster 2026-05-20T20:01:39.481Z]                      Kernel Time: 12.48ms
[taskcluster 2026-05-20T20:01:39.481Z]                        Wall Time: 37.355393995s
[taskcluster 2026-05-20T20:01:39.481Z]  Average Available System Memory: 14.46 GiB
[taskcluster 2026-05-20T20:01:39.481Z]       Average System Memory Used: 1.15 GiB
[taskcluster 2026-05-20T20:01:39.481Z]          Peak System Memory Used: 1.36 GiB
[taskcluster 2026-05-20T20:01:39.481Z]              Total System Memory: 15.61 GiB
[taskcluster 2026-05-20T20:01:39.481Z]                           Result: SUCCEEDED
[taskcluster 2026-05-20T20:01:39.482Z] === Task Finished ===
[taskcluster 2026-05-20T20:01:39.482Z] Task Duration: 37.356241317s
[taskcluster 2026-05-20T20:01:39.503Z] [mounts] Preserving cache: Moving "/home/task_177930725408634/cache0" to "/home/generic-worker/caches/Z4Ory1w1TwSjwUkRpNb_mA"
[taskcluster 2026-05-20T20:01:39.503Z] [mounts] Preserving cache: Moving "/home/task_177930725408634/cache1" to "/home/generic-worker/caches/XTSXoOp5QOmmDZQsBqupuA"