[taskcluster 2026-01-30T18:36:28.733Z] Worker Type (scriptworker-1/images) settings:
[taskcluster 2026-01-30T18:36:28.733Z]   {
[taskcluster 2026-01-30T18:36:28.733Z]     "config": {
[taskcluster 2026-01-30T18:36:28.733Z]       "deploymentId": ""
[taskcluster 2026-01-30T18:36:28.733Z]     },
[taskcluster 2026-01-30T18:36:28.733Z]     "generic-worker": {
[taskcluster 2026-01-30T18:36:28.733Z]       "config": {
[taskcluster 2026-01-30T18:36:28.733Z]         "headlessTasks": true
[taskcluster 2026-01-30T18:36:28.733Z]       },
[taskcluster 2026-01-30T18:36:28.733Z]       "engine": "multiuser",
[taskcluster 2026-01-30T18:36:28.733Z]       "go-arch": "amd64",
[taskcluster 2026-01-30T18:36:28.733Z]       "go-os": "linux",
[taskcluster 2026-01-30T18:36:28.733Z]       "go-version": "go1.25.5",
[taskcluster 2026-01-30T18:36:28.733Z]       "release": "https://github.com/taskcluster/taskcluster/releases/tag/v95.1.3",
[taskcluster 2026-01-30T18:36:28.733Z]       "revision": "300ac23a15bb11e577f3a3d116a570fde948337e",
[taskcluster 2026-01-30T18:36:28.733Z]       "source": "https://github.com/taskcluster/taskcluster/commits/300ac23a15bb11e577f3a3d116a570fde948337e",
[taskcluster 2026-01-30T18:36:28.733Z]       "version": "95.1.3"
[taskcluster 2026-01-30T18:36:28.733Z]     },
[taskcluster 2026-01-30T18:36:28.733Z]     "image": "projects/taskcluster-imaging/global/images/gw-fxci-gcp-l1-2404-amd64-headless-googlecompute-2026-01-14",
[taskcluster 2026-01-30T18:36:28.733Z]     "instance-id": "8309665890003142437",
[taskcluster 2026-01-30T18:36:28.733Z]     "instance-type": "projects/887720501152/machineTypes/c2-standard-4",
[taskcluster 2026-01-30T18:36:28.733Z]     "local-ipv4": "10.128.0.233",
[taskcluster 2026-01-30T18:36:28.733Z]     "project-id": "fxci-production-level1-workers",
[taskcluster 2026-01-30T18:36:28.733Z]     "public-hostname": "scriptworker-1-images-fbthwyhmrgmpe0ibivg0rq.c.fxci-production-level1-workers.internal",
[taskcluster 2026-01-30T18:36:28.733Z]     "public-ipv4": "136.114.186.129",
[taskcluster 2026-01-30T18:36:28.733Z]     "region": "us-central1",
[taskcluster 2026-01-30T18:36:28.733Z]     "zone": "us-central1-f"
[taskcluster 2026-01-30T18:36:28.733Z]   }
[taskcluster 2026-01-30T18:36:28.733Z] Task ID: Zvs8sd4AR-K85DnPZtWCrw
[taskcluster 2026-01-30T18:36:28.733Z] === Task Starting ===
[taskcluster 2026-01-30T18:36:30.820Z] [mounts] No existing writable directory cache 'scriptworker-level-1-checkouts-v3-7afeb851dd97df8f3607-IcInuB8VTrGMwdYQZoJ0kw' - creating /home/generic-worker/caches/W7gWErVoT3qk3UP5pvmcPQ
[taskcluster 2026-01-30T18:36:30.820Z] [mounts] Creating directory /home/task_176979818805755/cache0
[taskcluster 2026-01-30T18:36:30.830Z] [mounts] Successfully mounted writable directory cache '/home/task_176979818805755/cache0'
[taskcluster 2026-01-30T18:36:30.830Z] [mounts] Downloading task IcInuB8VTrGMwdYQZoJ0kw artifact public/image.tar.zst to /home/generic-worker/downloads/fS1F2U0QSoePQj4D_djqwA
[taskcluster 2026-01-30T18:36:33.593Z] [mounts] Downloaded 97545041 bytes with SHA256 ac62d9bdff9d8a7d318da86e6865e00ee4d88d4cd768da0af6c6b6f9f4e3db23 from task IcInuB8VTrGMwdYQZoJ0kw artifact public/image.tar.zst to /home/generic-worker/downloads/fS1F2U0QSoePQj4D_djqwA
[taskcluster:warn 2026-01-30T18:36:33.593Z] [mounts] Download /home/generic-worker/downloads/fS1F2U0QSoePQj4D_djqwA of task IcInuB8VTrGMwdYQZoJ0kw artifact public/image.tar.zst has SHA256 ac62d9bdff9d8a7d318da86e6865e00ee4d88d4cd768da0af6c6b6f9f4e3db23 but task payload does not declare a required value, so content authenticity cannot be verified
[taskcluster 2026-01-30T18:36:33.593Z] [mounts] Creating directory /home/task_176979818805755
[taskcluster 2026-01-30T18:36:33.613Z] [mounts] Copying /home/generic-worker/downloads/fS1F2U0QSoePQj4D_djqwA to /home/task_176979818805755/dockerimage
[taskcluster 2026-01-30T18:36:33.916Z] [mounts] Granting task_176979818805755 full control of file '/home/task_176979818805755/dockerimage'
[taskcluster 2026-01-30T18:36:34.158Z] [d2g] Loading docker image
[taskcluster 2026-01-30T18:36:38.135Z] [d2g] Loaded docker image "python3.11:latest"
[taskcluster 2026-01-30T18:36:38.135Z] Executing command 0: docker run -t --name taskcontainer_U68uBk7hSZy2KWTrkh1XFQ --memory-swap -1 --pids-limit -1 '--add-host=localhost.localdomain:127.0.0.1' -v /home/task_176979818805755/cache0:/builds/worker/checkouts --add-host=taskcluster:host-gateway --env-file 'env.list' 06a84e8d379fa55c0e958cbf740a67a87d142713f7f4367fd008b18a7351bc52 /usr/local/bin/run-task --scriptworker-checkout=/builds/worker/checkouts/vcs/ --task-cwd /builds/worker/checkouts/vcs -- sh -lxce 'uv run tox -e py311'
[setup 2026-01-30T18:36:39.922Z] run-task started in /
[setup 2026-01-30T18:36:39.922Z] Invoked by command: --scriptworker-checkout=/builds/worker/checkouts/vcs/ --task-cwd /builds/worker/checkouts/vcs -- sh -lxce uv run tox -e py311
[setup 2026-01-30T18:36:39.922Z] Python version: 3.11.12
[cache 2026-01-30T18:36:39.923Z] cache /builds/worker/checkouts is empty; writing requirements: gid=1000 uid=1000 version=1
[volume 2026-01-30T18:36:39.923Z] changing ownership of volume /builds/worker/.cache to 1000:1000
[volume 2026-01-30T18:36:39.924Z] volume /builds/worker/checkouts is a cache
[setup 2026-01-30T18:36:39.924Z] running as worker:worker
[vcs 2026-01-30T18:36:39.924Z] executing ['git', 'config', '--global', '--add', 'safe.directory', '/builds/worker/checkouts/vcs']
[vcs 2026-01-30T18:36:39.926Z] executing ['git', 'clone', 'https://github.com/mozilla-releng/scriptworker', '/builds/worker/checkouts/vcs']
[vcs 2026-01-30T18:36:39.927Z] Cloning into '/builds/worker/checkouts/vcs'...
[vcs 2026-01-30T18:36:40.654Z] executing ['git', 'fetch', '--no-tags', 'https://github.com/ahal/scriptworker', 'ahal/push-nxqwovtprvvs']
[vcs 2026-01-30T18:36:40.893Z] From https://github.com/ahal/scriptworker
[vcs 2026-01-30T18:36:40.893Z]  * branch            ahal/push-nxqwovtprvvs -> FETCH_HEAD
[vcs 2026-01-30T18:36:40.895Z] executing ['git', 'checkout', '-f', '-B', 'ahal/push-nxqwovtprvvs', 'd22b0474779e8c7274cb353101460cb6654d3b51']
[vcs 2026-01-30T18:36:40.968Z] Switched to a new branch 'ahal/push-nxqwovtprvvs'
[vcs 2026-01-30T18:36:40.968Z] cleaning git checkout...
[vcs 2026-01-30T18:36:40.968Z] executing ['git', 'clean', '-nxdff']
[vcs 2026-01-30T18:36:40.970Z] removing []
[vcs 2026-01-30T18:36:40.970Z] successfully cleaned git checkout!
[vcs 2026-01-30T18:36:40.971Z] TinderboxPrint:<a href='https://github.com/ahal/scriptworker/commit/d22b0474779e8c7274cb353101460cb6654d3b51' title='Built from scriptworker commit d22b0474779e8c7274cb353101460cb6654d3b51'>d22b0474779e8c7274cb353101460cb6654d3b51</a>
[task 2026-01-30T18:36:40.971Z] executing ['sh', '-lxce', 'uv run tox -e py311']
[task 2026-01-30T18:36:40.972Z] + id -u
[task 2026-01-30T18:36:40.973Z] + [ 1000 -eq 0 ]
[task 2026-01-30T18:36:40.973Z] + PATH=/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games
[task 2026-01-30T18:36:40.974Z] + export PATH
[task 2026-01-30T18:36:40.974Z] + [ $  ]
[task 2026-01-30T18:36:40.974Z] + [  ]
[task 2026-01-30T18:36:40.974Z] + id -u
[task 2026-01-30T18:36:40.975Z] + [ 1000 -eq 0 ]
[task 2026-01-30T18:36:40.975Z] + PS1=$ 
[task 2026-01-30T18:36:40.975Z] + [ -d /etc/profile.d ]
[task 2026-01-30T18:36:40.975Z] + [ -r /etc/profile.d/*.sh ]
[task 2026-01-30T18:36:40.975Z] + unset i
[task 2026-01-30T18:36:40.975Z] + [ -n  ]
[task 2026-01-30T18:36:40.975Z] + [ -d /builds/worker/bin ]
[task 2026-01-30T18:36:40.975Z] + [ -d /builds/worker/.local/bin ]
[task 2026-01-30T18:36:40.975Z] + uv run tox -e py311
[task 2026-01-30T18:36:41.021Z] Using CPython 3.11.12 interpreter at: /usr/local/bin/python3
[task 2026-01-30T18:36:41.021Z] Creating virtual environment at: .venv
[task 2026-01-30T18:36:42.457Z]    Building scriptworker @ file:///builds/worker/checkouts/vcs
[task 2026-01-30T18:36:42.521Z] Downloading uv (21.6MiB)
[task 2026-01-30T18:36:42.521Z] Downloading cryptography (4.2MiB)
[task 2026-01-30T18:36:42.522Z] Downloading pygments (1.2MiB)
[task 2026-01-30T18:36:42.523Z] Downloading aiohttp (1.7MiB)
[task 2026-01-30T18:36:42.524Z] Downloading virtualenv (5.7MiB)
[task 2026-01-30T18:36:42.527Z] Downloading black (1.7MiB)
[task 2026-01-30T18:36:42.529Z] Downloading mypy (12.8MiB)
[task 2026-01-30T18:36:42.886Z]    Building docopt==0.6.2
[task 2026-01-30T18:36:43.257Z]  Downloading aiohttp
[task 2026-01-30T18:36:43.365Z]  Downloading virtualenv
[task 2026-01-30T18:36:43.402Z]  Downloading black
[task 2026-01-30T18:36:43.449Z]  Downloading cryptography
[task 2026-01-30T18:36:43.532Z]  Downloading uv
[task 2026-01-30T18:36:43.576Z]       Built docopt==0.6.2
[task 2026-01-30T18:36:43.592Z]  Downloading pygments
[task 2026-01-30T18:36:43.682Z]       Built scriptworker @ file:///builds/worker/checkouts/vcs
[task 2026-01-30T18:36:43.762Z]  Downloading mypy
[task 2026-01-30T18:36:43.763Z] warning: Failed to hardlink files; falling back to full copy. This may lead to degraded performance.
[task 2026-01-30T18:36:43.763Z]          If the cache and target directories are on different filesystems, hardlinking may not be supported.
[task 2026-01-30T18:36:43.763Z]          If this is intentional, set `export UV_LINK_MODE=copy` or use `--link-mode=copy` to suppress this warning.
[task 2026-01-30T18:36:43.911Z] Installed 104 packages in 148ms
[task 2026-01-30T18:36:44.439Z] .pkg: remove tox env folder /builds/worker/checkouts/vcs/.tox/.pkg
[task 2026-01-30T18:36:44.443Z] py311: venv> .venv/bin/uv venv -p /builds/worker/checkouts/vcs/.venv/bin/python --allow-existing --python-preference system /builds/worker/checkouts/vcs/.tox/py311
[task 2026-01-30T18:36:44.529Z] .pkg: venv> .venv/bin/uv venv -p /builds/worker/checkouts/vcs/.venv/bin/python --allow-existing --python-preference system /builds/worker/checkouts/vcs/.tox/.pkg
[task 2026-01-30T18:36:44.572Z] .pkg: install_requires> .venv/bin/uv pip install hatchling
[task 2026-01-30T18:36:44.695Z] .pkg: _optional_hooks> python /builds/worker/checkouts/vcs/.venv/lib/python3.11/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-01-30T18:36:44.729Z] .pkg: get_requires_for_build_editable> python /builds/worker/checkouts/vcs/.venv/lib/python3.11/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-01-30T18:36:44.822Z] .pkg: install_requires_for_build_editable> .venv/bin/uv pip install 'editables~=0.3'
[task 2026-01-30T18:36:44.872Z] .pkg: build_editable> python /builds/worker/checkouts/vcs/.venv/lib/python3.11/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-01-30T18:36:44.952Z] py311: install_package_deps> .venv/bin/uv 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[format-nongpl]' taskcluster-taskgraph 'taskcluster>=40'
[task 2026-01-30T18:36:45.592Z] py311: install_package> .venv/bin/uv pip install --reinstall --no-deps scriptworker@/builds/worker/checkouts/vcs/.tox/.tmp/package/1/scriptworker-62.3.0-py3-none-any.whl
[task 2026-01-30T18:36:45.649Z] py311: commands[0]> coverage run --source=src/scriptworker --branch --rcfile tox.ini -m pytest tests
[task 2026-01-30T18:36:51.257Z] ============================= test session starts ==============================
[task 2026-01-30T18:36:51.257Z] platform linux -- Python 3.11.12, pytest-8.4.2, pluggy-1.6.0
[task 2026-01-30T18:36:51.257Z] cachedir: .tox/py311/.pytest_cache
[task 2026-01-30T18:36:51.257Z] Test order randomisation NOT enabled. Enable with --random-order or --random-order-bucket=<bucket_type>
[task 2026-01-30T18:36:51.257Z] rootdir: /builds/worker/checkouts/vcs
[task 2026-01-30T18:36:51.257Z] configfile: pyproject.toml
[task 2026-01-30T18:36:51.257Z] plugins: random-order-1.2.0, asyncio-0.26.0, mock-3.15.1
[task 2026-01-30T18:36:51.257Z] asyncio: mode=Mode.AUTO, asyncio_default_fixture_loop_scope=None, asyncio_default_test_loop_scope=function
[task 2026-01-30T18:36:51.257Z] collected 687 items
[task 2026-01-30T18:36:51.257Z] 
[task 2026-01-30T18:36:51.397Z] tests/test_artifacts.py .........................................        [  5%]
[task 2026-01-30T18:36:51.552Z] tests/test_client.py ............................                        [ 10%]
[task 2026-01-30T18:36:51.660Z] tests/test_config.py ....................................                [ 15%]
[task 2026-01-30T18:36:51.705Z] tests/test_context.py .............                                      [ 17%]
[task 2026-01-30T18:36:51.773Z] tests/test_cot_generate.py ......                                        [ 18%]
[task 2026-01-30T18:36:51.995Z] tests/test_cot_verify.py ............................................... [ 24%]
[task 2026-01-30T18:36:55.159Z] ........................................................................ [ 35%]
[task 2026-01-30T18:36:56.195Z] ........................................................................ [ 45%]
[task 2026-01-30T18:36:56.321Z] .....................                                                    [ 48%]
[task 2026-01-30T18:36:56.336Z] tests/test_ed25519.py ........                                           [ 50%]
[task 2026-01-30T18:36:56.751Z] tests/test_github.py ................................................... [ 57%]
[task 2026-01-30T18:36:56.770Z] ...                                                                      [ 57%]
[task 2026-01-30T18:36:56.782Z] tests/test_integration.py ssssssssssss                                   [ 59%]
[task 2026-01-30T18:36:56.846Z] tests/test_log.py ..........                                             [ 61%]
[task 2026-01-30T18:36:56.857Z] tests/test_production.py sssssssssss                                     [ 62%]
[task 2026-01-30T18:36:59.387Z] tests/test_task.py ..................................................... [ 70%]
[task 2026-01-30T18:37:06.867Z] ...............................................................          [ 79%]
[task 2026-01-30T18:37:09.886Z] tests/test_task_process.py ....                                          [ 80%]
[task 2026-01-30T18:37:10.519Z] tests/test_utils.py .................................................... [ 87%]
[task 2026-01-30T18:37:10.694Z] ............................................................             [ 96%]
[task 2026-01-30T18:37:13.208Z] tests/test_worker.py ..............Task was destroyed but it is pending!
[task 2026-01-30T18:37:13.208Z] task: <Task pending name='Task-1496' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-01-30T18:37:13.208Z] /usr/local/lib/python3.11/asyncio/base_events.py:679: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2026-01-30T18:37:13.208Z]   self._ready.clear()
[task 2026-01-30T18:37:13.208Z] RuntimeWarning: Enable tracemalloc to get the object allocation traceback
[task 2026-01-30T18:37:13.208Z] Task was destroyed but it is pending!
[task 2026-01-30T18:37:13.208Z] task: <Task cancelling name='Task-1516' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-01-30T18:37:13.208Z] Task was destroyed but it is pending!
[task 2026-01-30T18:37:13.209Z] task: <Task cancelling name='Task-1545' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-01-30T18:37:13.209Z] Task was destroyed but it is pending!
[task 2026-01-30T18:37:13.209Z] task: <Task cancelling name='Task-1553' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-01-30T18:37:13.209Z] Task was destroyed but it is pending!
[task 2026-01-30T18:37:13.209Z] task: <Task cancelling name='Task-1559' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-01-30T18:37:13.209Z] Task was destroyed but it is pending!
[task 2026-01-30T18:37:13.209Z] task: <Task cancelling name='Task-1566' coro=<noop_async() running at /builds/worker/checkouts/vcs/tests/__init__.py:121>>
[task 2026-01-30T18:37:13.448Z] ..........                            [100%]
[task 2026-01-30T18:37:13.448Z] 
[task 2026-01-30T18:37:13.448Z] =============================== warnings summary ===============================
[task 2026-01-30T18:37:13.449Z] tests/conftest.py:79
[task 2026-01-30T18:37:13.449Z]   /builds/worker/checkouts/vcs/tests/conftest.py:79: PytestRemovedIn9Warning: Marks applied to fixtures have no effect
[task 2026-01-30T18:37:13.449Z]   See docs: https://docs.pytest.org/en/stable/deprecations.html#applying-a-mark-to-a-fixture-function
[task 2026-01-30T18:37:13.449Z]     @pytest.mark.asyncio
[task 2026-01-30T18:37:13.449Z] 
[task 2026-01-30T18:37:13.449Z] tests/conftest.py:88
[task 2026-01-30T18:37:13.449Z]   /builds/worker/checkouts/vcs/tests/conftest.py:88: PytestRemovedIn9Warning: Marks applied to fixtures have no effect
[task 2026-01-30T18:37:13.449Z]   See docs: https://docs.pytest.org/en/stable/deprecations.html#applying-a-mark-to-a-fixture-function
[task 2026-01-30T18:37:13.449Z]     @pytest.mark.asyncio
[task 2026-01-30T18:37:13.449Z] 
[task 2026-01-30T18:37:13.449Z] tests/conftest.py:97
[task 2026-01-30T18:37:13.449Z]   /builds/worker/checkouts/vcs/tests/conftest.py:97: PytestRemovedIn9Warning: Marks applied to fixtures have no effect
[task 2026-01-30T18:37:13.449Z]   See docs: https://docs.pytest.org/en/stable/deprecations.html#applying-a-mark-to-a-fixture-function
[task 2026-01-30T18:37:13.449Z]     @pytest.mark.asyncio
[task 2026-01-30T18:37:13.449Z] 
[task 2026-01-30T18:37:13.449Z] tests/test_worker.py::test_mocker_run_tasks_noop
[task 2026-01-30T18:37:13.449Z] tests/test_worker.py::test_mocker_upload_artifacts_uncaught_exception
[task 2026-01-30T18:37:13.449Z] tests/test_worker.py::test_run_tasks_killed
[task 2026-01-30T18:37:13.449Z] tests/test_worker.py::test_run_tasks_cancel_claim_work
[task 2026-01-30T18:37:13.449Z]   /usr/local/lib/python3.11/asyncio/base_events.py:679: RuntimeWarning: coroutine 'noop_async' was never awaited
[task 2026-01-30T18:37:13.449Z]     self._ready.clear()
[task 2026-01-30T18:37:13.449Z]   Enable tracemalloc to get traceback where the object was allocated.
[task 2026-01-30T18:37:13.449Z]   See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.
[task 2026-01-30T18:37:13.449Z] 
[task 2026-01-30T18:37:13.449Z] -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
[task 2026-01-30T18:37:13.449Z] ================= 664 passed, 23 skipped, 7 warnings in 26.07s =================
[task 2026-01-30T18:37:13.743Z] .pkg: _exit> python /builds/worker/checkouts/vcs/.venv/lib/python3.11/site-packages/pyproject_api/_backend.py True hatchling.build
[task 2026-01-30T18:37:13.763Z]   py311: OK (29.32=setup[1.23]+cmd[28.09] seconds)
[task 2026-01-30T18:37:13.763Z]   congratulations :) (29.38 seconds)
[taskcluster 2026-01-30T18:37:14.118Z]                        Exit Code: 0
[taskcluster 2026-01-30T18:37:14.118Z]                        User Time: 16.1ms
[taskcluster 2026-01-30T18:37:14.118Z]                      Kernel Time: 13.953ms
[taskcluster 2026-01-30T18:37:14.118Z]                        Wall Time: 35.982761142s
[taskcluster 2026-01-30T18:37:14.118Z]  Average Available System Memory: 14.74 GiB
[taskcluster 2026-01-30T18:37:14.118Z]       Average System Memory Used: 895.71 MiB
[taskcluster 2026-01-30T18:37:14.118Z]          Peak System Memory Used: 967.57 MiB
[taskcluster 2026-01-30T18:37:14.118Z]              Total System Memory: 15.62 GiB
[taskcluster 2026-01-30T18:37:14.118Z]                           Result: SUCCEEDED
[taskcluster 2026-01-30T18:37:14.119Z] === Task Finished ===
[taskcluster 2026-01-30T18:37:14.119Z] Task Duration: 35.983443935s
[taskcluster 2026-01-30T18:37:14.168Z] [mounts] Preserving cache: Moving "/home/task_176979818805755/cache0" to "/home/generic-worker/caches/W7gWErVoT3qk3UP5pvmcPQ"