2025-11-01 00:21:49.984287 | Job console starting...
2025-11-01 00:21:49.996419 | Updating repositories
2025-11-01 00:21:50.114362 | Preparing job workspace
2025-11-01 00:21:55.401344 | Running Ansible setup...
2025-11-01 00:22:02.527627 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-01 00:22:03.210475 | 
2025-11-01 00:22:03.210595 | PLAY [localhost]
2025-11-01 00:22:03.219361 | 
2025-11-01 00:22:03.219435 | TASK [Gathering Facts]
2025-11-01 00:22:04.341964 | localhost | ok
2025-11-01 00:22:04.371082 | 
2025-11-01 00:22:04.371277 | TASK [Setup log path fact]
2025-11-01 00:22:04.396237 | localhost | ok
2025-11-01 00:22:04.420958 | 
2025-11-01 00:22:04.421057 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-01 00:22:04.455088 | localhost | ok
2025-11-01 00:22:04.466983 | 
2025-11-01 00:22:04.467132 | TASK [emit-job-header : Print job information]
2025-11-01 00:22:04.521624 | # Job Information
2025-11-01 00:22:04.521919 | Ansible Version: 2.15.12
2025-11-01 00:22:04.521987 | Job: ansible-test-sanity-docker-devel
2025-11-01 00:22:04.522032 | Pipeline: periodic
2025-11-01 00:22:04.522143 | Executor: ze02.softwarefactory-project.io
2025-11-01 00:22:04.522189 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-11-01 00:22:04.522235 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/190/ansible/190a877763804cc59fdb5db3e624ecc9/
2025-11-01 00:22:04.522277 | Event ID: a664f74adefa4145bbf2cab5da247121
2025-11-01 00:22:04.530875 | 
2025-11-01 00:22:04.531040 | LOOP [emit-job-header : Print node information]
2025-11-01 00:22:04.655141 | localhost | ok:
2025-11-01 00:22:04.655346 | localhost | # Node Information
2025-11-01 00:22:04.655373 | localhost | Inventory Hostname: controller
2025-11-01 00:22:04.655393 | localhost | Hostname: ip-172-16-57-173
2025-11-01 00:22:04.655412 | localhost | Username: zuul-worker
2025-11-01 00:22:04.655431 | localhost | Distro: Fedora 37
2025-11-01 00:22:04.655449 | localhost | Provider: ansible-us-east-2
2025-11-01 00:22:04.655466 | localhost | Region: us-east-2
2025-11-01 00:22:04.655483 | localhost | Label: ansible-fedora-37-1vcpu
2025-11-01 00:22:04.655499 | localhost | Product Name: t3.small
2025-11-01 00:22:04.655516 | localhost | Interface IP: 18.222.128.9
2025-11-01 00:22:04.672975 | 
2025-11-01 00:22:04.673073 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-11-01 00:22:05.178959 | localhost -> localhost | changed
2025-11-01 00:22:05.184894 | 
2025-11-01 00:22:05.185021 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-11-01 00:22:06.184485 | localhost -> localhost | changed
2025-11-01 00:22:06.203249 | 
2025-11-01 00:22:06.203304 | PLAY [all:!appliance*]
2025-11-01 00:22:06.218461 | 
2025-11-01 00:22:06.218531 | TASK [include_role : start-zuul-console]
2025-11-01 00:22:06.239067 | controller | ok
2025-11-01 00:22:06.252283 | 
2025-11-01 00:22:06.252362 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-11-01 00:22:06.955488 | controller | ok
2025-11-01 00:22:06.971241 | 
2025-11-01 00:22:06.971370 | TASK [use-our-mirror : Retrieve the IP address]
2025-11-01 00:22:08.633794 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-11-01 00:22:08.652591 | 
2025-11-01 00:22:08.652750 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-11-01 00:22:08.791834 | controller | skipping: Conditional result was False
2025-11-01 00:22:08.805123 | 
2025-11-01 00:22:08.805273 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-11-01 00:22:08.843007 | controller | skipping: Conditional result was False
2025-11-01 00:22:08.855774 | 
2025-11-01 00:22:08.855914 | TASK [use-our-mirror : Create the podman configuration directory]
2025-11-01 00:22:08.883901 | controller | skipping: Conditional result was False
2025-11-01 00:22:08.896278 | 
2025-11-01 00:22:08.896420 | TASK [use-our-mirror : Copy the podman configuration]
2025-11-01 00:22:08.924813 | controller | skipping: Conditional result was False
2025-11-01 00:22:08.937517 | 
2025-11-01 00:22:08.937656 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-11-01 00:22:08.965632 | controller | skipping: Conditional result was False
2025-11-01 00:22:08.978983 | 
2025-11-01 00:22:08.979154 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-11-01 00:22:09.017516 | controller | skipping: Conditional result was False
2025-11-01 00:22:09.043068 | 
2025-11-01 00:22:09.043401 | TASK [Disable Fedora Modular]
2025-11-01 00:22:09.775314 | controller | changed
2025-11-01 00:22:09.787827 | 
2025-11-01 00:22:09.787974 | TASK [Enable EPEL]
2025-11-01 00:22:09.816420 | controller | skipping: Conditional result was False
2025-11-01 00:22:09.832576 | 
2025-11-01 00:22:09.832776 | TASK [Register the RHEL node]
2025-11-01 00:22:10.000783 | 
2025-11-01 00:22:10.000972 | TASK [Show the subscription-manager status]
2025-11-01 00:22:10.184425 | controller | skipping: Conditional result was False
2025-11-01 00:22:10.191243 | 
2025-11-01 00:22:10.191324 | TASK [Enable EPEL on RHEL]
2025-11-01 00:22:10.333104 | controller | skipping: Conditional result was False
2025-11-01 00:22:10.343035 | 
2025-11-01 00:22:10.343164 | TASK [Install git and tox]
2025-11-01 00:23:45.758533 | controller | changed
2025-11-01 00:23:45.766084 | 
2025-11-01 00:23:45.766212 | TASK [include_role : prepare-workspace]
2025-11-01 00:23:45.797274 | controller | ok
2025-11-01 00:23:45.819308 | 
2025-11-01 00:23:45.819427 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-11-01 00:23:46.378722 | controller | ok
2025-11-01 00:23:46.394829 | 
2025-11-01 00:23:46.395051 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-11-01 00:23:59.974865 | controller | Output suppressed because no_log was given
2025-11-01 00:23:59.986127 | 
2025-11-01 00:23:59.986224 | TASK [include_role : prepare-workspace-openshift]
2025-11-01 00:24:00.003717 | controller | skipping: Conditional result was False
2025-11-01 00:24:00.030378 | 
2025-11-01 00:24:00.030456 | PLAY [all:!appliance]
2025-11-01 00:24:00.049494 | 
2025-11-01 00:24:00.049599 | TASK [Run add-build-sshkey role (RSA)]
2025-11-01 00:24:00.074870 | controller | ok
2025-11-01 00:24:00.096629 | 
2025-11-01 00:24:00.096779 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-01 00:24:00.317476 | controller -> localhost | ok
2025-11-01 00:24:00.325725 | 
2025-11-01 00:24:00.325842 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-01 00:24:00.358684 | controller | ok
2025-11-01 00:24:00.407383 | controller | included: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-01 00:24:00.415238 | 
2025-11-01 00:24:00.415411 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-01 00:24:00.955453 | controller -> localhost | Generating public/private rsa key pair.
2025-11-01 00:24:00.956094 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/190a877763804cc59fdb5db3e624ecc9_id_rsa.
2025-11-01 00:24:00.956163 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/190a877763804cc59fdb5db3e624ecc9_id_rsa.pub.
2025-11-01 00:24:00.956224 | controller -> localhost | The key fingerprint is:
2025-11-01 00:24:00.956261 | controller -> localhost | SHA256:GCLq4fJIEWchX07HgPl5NKgSthFPhZ1THIeZH4E94tE zuul-build-sshkey
2025-11-01 00:24:00.956318 | controller -> localhost | The key's randomart image is:
2025-11-01 00:24:00.956350 | controller -> localhost | +---[RSA 2048]----+
2025-11-01 00:24:00.956414 | controller -> localhost | | o.o*=B+Oo.      |
2025-11-01 00:24:00.956464 | controller -> localhost | | +=+==.%.E       |
2025-11-01 00:24:00.956494 | controller -> localhost | |..==+.* = o      |
2025-11-01 00:24:00.956518 | controller -> localhost | | ++o + = .       |
2025-11-01 00:24:00.956580 | controller -> localhost | |.o.   o S        |
2025-11-01 00:24:00.956647 | controller -> localhost | |o o              |
2025-11-01 00:24:00.956715 | controller -> localhost | |.+               |
2025-11-01 00:24:00.956746 | controller -> localhost | |oo               |
2025-11-01 00:24:00.956812 | controller -> localhost | |. .              |
2025-11-01 00:24:00.956868 | controller -> localhost | +----[SHA256]-----+
2025-11-01 00:24:00.956981 | controller -> localhost | ok: Runtime: 0:00:00.151946
2025-11-01 00:24:00.978570 | 
2025-11-01 00:24:00.978770 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-01 00:24:01.010822 | controller | ok
2025-11-01 00:24:01.023349 | controller | included: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-01 00:24:01.036042 | 
2025-11-01 00:24:01.036163 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-01 00:24:01.060693 | controller | skipping: Conditional result was False
2025-11-01 00:24:01.068529 | 
2025-11-01 00:24:01.068635 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-01 00:24:02.134400 | controller | changed
2025-11-01 00:24:02.142586 | 
2025-11-01 00:24:02.142716 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-01 00:24:02.790382 | controller | ok
2025-11-01 00:24:02.802204 | 
2025-11-01 00:24:02.802344 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-01 00:24:04.536129 | controller | changed
2025-11-01 00:24:04.550989 | 
2025-11-01 00:24:04.551163 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-01 00:24:06.461821 | controller | changed
2025-11-01 00:24:06.478529 | 
2025-11-01 00:24:06.478739 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-01 00:24:06.497824 | controller | skipping: Conditional result was False
2025-11-01 00:24:06.513763 | 
2025-11-01 00:24:06.513930 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-01 00:24:06.895168 | controller -> localhost | changed
2025-11-01 00:24:06.906599 | 
2025-11-01 00:24:06.906689 | TASK [add-build-sshkey : Add back temp key]
2025-11-01 00:24:07.206780 | controller -> localhost | Identity added: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/190a877763804cc59fdb5db3e624ecc9_id_rsa (zuul-build-sshkey)
2025-11-01 00:24:07.207049 | controller -> localhost | ok: Runtime: 0:00:00.013469
2025-11-01 00:24:07.215601 | 
2025-11-01 00:24:07.215696 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-01 00:24:07.720537 | controller | ok
2025-11-01 00:24:07.733410 | 
2025-11-01 00:24:07.733563 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-01 00:24:07.770576 | controller | skipping: Conditional result was False
2025-11-01 00:24:07.795976 | 
2025-11-01 00:24:07.796148 | TASK [Run add-build-sshkey role (ECDSA)]
2025-11-01 00:24:07.834500 | controller | ok
2025-11-01 00:24:07.864480 | 
2025-11-01 00:24:07.864614 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-11-01 00:24:08.143843 | controller -> localhost | ok
2025-11-01 00:24:08.150200 | 
2025-11-01 00:24:08.150278 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-11-01 00:24:08.179616 | controller | ok
2025-11-01 00:24:08.191600 | controller | included: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-11-01 00:24:08.197700 | 
2025-11-01 00:24:08.197767 | TASK [add-build-sshkey : Create Temp SSH key]
2025-11-01 00:24:08.497613 | controller -> localhost | Generating public/private ecdsa key pair.
2025-11-01 00:24:08.497817 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/190a877763804cc59fdb5db3e624ecc9_id_ecdsa.
2025-11-01 00:24:08.497848 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/190a877763804cc59fdb5db3e624ecc9_id_ecdsa.pub.
2025-11-01 00:24:08.497879 | controller -> localhost | The key fingerprint is:
2025-11-01 00:24:08.497899 | controller -> localhost | SHA256:C1yC0ebCww4hlsFRPcCwBn2FbDgHrCPpzk86duISb/g zuul-build-sshkey
2025-11-01 00:24:08.497918 | controller -> localhost | The key's randomart image is:
2025-11-01 00:24:08.497936 | controller -> localhost | +---[ECDSA 521]---+
2025-11-01 00:24:08.497955 | controller -> localhost | |o*O*++.          |
2025-11-01 00:24:08.497972 | controller -> localhost | |o+B.*=o          |
2025-11-01 00:24:08.497990 | controller -> localhost | |.* O.oo .        |
2025-11-01 00:24:08.498010 | controller -> localhost | |* . =..o         |
2025-11-01 00:24:08.498028 | controller -> localhost | |o. o oo S        |
2025-11-01 00:24:08.498046 | controller -> localhost | |..  .  . .       |
2025-11-01 00:24:08.498063 | controller -> localhost | |o+ .    .        |
2025-11-01 00:24:08.498081 | controller -> localhost | |o*=.             |
2025-11-01 00:24:08.498099 | controller -> localhost | |+=E.             |
2025-11-01 00:24:08.498117 | controller -> localhost | +----[SHA256]-----+
2025-11-01 00:24:08.498169 | controller -> localhost | ok: Runtime: 0:00:00.014401
2025-11-01 00:24:08.504742 | 
2025-11-01 00:24:08.504812 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-11-01 00:24:08.535847 | controller | ok
2025-11-01 00:24:08.543633 | controller | included: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-11-01 00:24:08.553270 | 
2025-11-01 00:24:08.553394 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-11-01 00:24:08.577651 | controller | skipping: Conditional result was False
2025-11-01 00:24:08.584998 | 
2025-11-01 00:24:08.585076 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-11-01 00:24:09.043477 | controller | changed
2025-11-01 00:24:09.049284 | 
2025-11-01 00:24:09.049458 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-11-01 00:24:09.391889 | controller | ok
2025-11-01 00:24:09.404917 | 
2025-11-01 00:24:09.405076 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-11-01 00:24:10.807765 | controller | changed
2025-11-01 00:24:10.815931 | 
2025-11-01 00:24:10.816066 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-11-01 00:24:12.263833 | controller | changed
2025-11-01 00:24:12.281420 | 
2025-11-01 00:24:12.281650 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-11-01 00:24:12.310851 | controller | skipping: Conditional result was False
2025-11-01 00:24:12.326532 | 
2025-11-01 00:24:12.326779 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-11-01 00:24:12.588991 | controller -> localhost | changed
2025-11-01 00:24:12.606097 | 
2025-11-01 00:24:12.606237 | TASK [add-build-sshkey : Add back temp key]
2025-11-01 00:24:12.947742 | controller -> localhost | Identity added: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/190a877763804cc59fdb5db3e624ecc9_id_ecdsa (zuul-build-sshkey)
2025-11-01 00:24:12.947950 | controller -> localhost | ok: Runtime: 0:00:00.007347
2025-11-01 00:24:12.954180 | 
2025-11-01 00:24:12.954248 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-11-01 00:24:13.344859 | controller | ok
2025-11-01 00:24:13.352525 | 
2025-11-01 00:24:13.352696 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-11-01 00:24:13.379320 | controller | skipping: Conditional result was False
2025-11-01 00:24:13.395205 | 
2025-11-01 00:24:13.395345 | TASK [include_role : remove-zuul-sshkey]
2025-11-01 00:24:13.412047 | controller | skipping: Conditional result was False
2025-11-01 00:24:13.422202 | 
2025-11-01 00:24:13.422362 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-11-01 00:24:13.778814 | controller | ok: "logs"
2025-11-01 00:24:13.779533 | controller | ok: All items complete
2025-11-01 00:24:13.779614 | 
2025-11-01 00:24:14.154291 | controller | ok: "artifacts"
2025-11-01 00:24:14.416972 | controller | ok: "docs"
2025-11-01 00:24:14.433412 | 
2025-11-01 00:24:14.433592 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-11-01 00:24:14.806590 | controller | changed: "logs"
2025-11-01 00:24:15.135710 | controller | changed: "artifacts"
2025-11-01 00:24:15.461356 | controller | changed: "docs"
2025-11-01 00:24:15.519969 | 
2025-11-01 00:24:15.520078 | PLAY RECAP
2025-11-01 00:24:15.520134 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-11-01 00:24:15.520170 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-11-01 00:24:15.520196 | 
2025-11-01 00:24:15.636995 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-11-01 00:24:15.637841 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-01 00:24:16.209164 | 
2025-11-01 00:24:16.209292 | PLAY [all]
2025-11-01 00:24:16.231317 | 
2025-11-01 00:24:16.231444 | TASK [Install binary dependencies]
2025-11-01 00:24:16.271737 | controller | ok
2025-11-01 00:24:16.291640 | 
2025-11-01 00:24:16.291810 | TASK [bindep : Include find tasks]
2025-11-01 00:24:16.333526 | controller | ok
2025-11-01 00:24:16.344999 | controller | included: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-11-01 00:24:16.353979 | 
2025-11-01 00:24:16.354083 | TASK [bindep : Look for bindep.txt]
2025-11-01 00:24:16.858109 | controller | ok
2025-11-01 00:24:16.871452 | 
2025-11-01 00:24:16.871620 | TASK [bindep : Define bindep_file fact]
2025-11-01 00:24:16.888178 | controller | skipping: Conditional result was False
2025-11-01 00:24:16.900861 | 
2025-11-01 00:24:16.901069 | TASK [bindep : Look for other-requirements.txt]
2025-11-01 00:24:17.261001 | controller | ok
2025-11-01 00:24:17.268397 | 
2025-11-01 00:24:17.268529 | TASK [bindep : Define bindep_file fact]
2025-11-01 00:24:17.303995 | controller | skipping: Conditional result was False
2025-11-01 00:24:17.311863 | 
2025-11-01 00:24:17.312150 | TASK [bindep : Look for bindep fallback file]
2025-11-01 00:24:17.347660 | controller | skipping: Conditional result was False
2025-11-01 00:24:17.355806 | 
2025-11-01 00:24:17.355922 | TASK [bindep : Define bindep_file fact]
2025-11-01 00:24:17.380543 | controller | skipping: Conditional result was False
2025-11-01 00:24:17.388501 | 
2025-11-01 00:24:17.388611 | TASK [bindep : Include bindep tasks]
2025-11-01 00:24:17.414340 | controller | skipping: Conditional result was False
2025-11-01 00:24:17.423799 | 
2025-11-01 00:24:17.423926 | TASK [bindep : Include install tasks]
2025-11-01 00:24:17.448347 | controller | skipping: Conditional result was False
2025-11-01 00:24:17.456422 | 
2025-11-01 00:24:17.456542 | LOOP [bindep : Include package tasks]
2025-11-01 00:24:17.512301 | 
2025-11-01 00:24:17.512470 | TASK [Run test-setup role]
2025-11-01 00:24:17.530998 | controller | ok
2025-11-01 00:24:17.549443 | 
2025-11-01 00:24:17.549566 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-11-01 00:24:17.884894 | controller | ok
2025-11-01 00:24:17.892815 | 
2025-11-01 00:24:17.892930 | TASK [test-setup : Run tools/test-setup.sh]
2025-11-01 00:24:18.035128 | controller | skipping: Conditional result was False
2025-11-01 00:24:18.068487 | 
2025-11-01 00:24:18.068597 | PLAY RECAP
2025-11-01 00:24:18.068654 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-01 00:24:18.068717 | 
2025-11-01 00:24:18.180754 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-11-01 00:24:18.181647 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-01 00:24:18.748132 | 
2025-11-01 00:24:18.748285 | PLAY [controller]
2025-11-01 00:24:18.769821 | 
2025-11-01 00:24:18.769980 | TASK [Create the /root directory]
2025-11-01 00:24:19.519182 | controller | ok
2025-11-01 00:24:19.527553 | 
2025-11-01 00:24:19.527725 | TASK [Install glibc-langpack-en]
2025-11-01 00:24:27.704644 | controller | ok: Nothing to do
2025-11-01 00:24:27.716400 | 
2025-11-01 00:24:27.716583 | TASK [Ensure controller directory exists]
2025-11-01 00:24:28.208236 | controller | changed
2025-11-01 00:24:28.222085 | 
2025-11-01 00:24:28.222454 | TASK [Install container runtime]
2025-11-01 00:24:28.302940 | controller | ok
2025-11-01 00:24:28.362943 | 
2025-11-01 00:24:28.363094 | LOOP [ensure-podman : Find distribution installation]
2025-11-01 00:24:28.401478 | controller | ok: "/var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-11-01 00:24:28.419351 | controller | included: /var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-11-01 00:24:28.429121 | 
2025-11-01 00:24:28.429260 | TASK [ensure-podman : Install podman (RedHat)]
2025-11-01 00:25:52.600753 | controller | changed
2025-11-01 00:25:52.617986 | 
2025-11-01 00:25:52.618376 | TASK [ensure-podman : Fetch podman version]
2025-11-01 00:25:53.466072 | controller | Client:       Podman Engine
2025-11-01 00:25:53.492313 | controller | Version:      4.6.2
2025-11-01 00:25:53.492372 | controller | API Version:  4.6.2
2025-11-01 00:25:53.492389 | controller | Go Version:   go1.19.12
2025-11-01 00:25:53.492423 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-11-01 00:25:53.492439 | controller | OS/Arch:      linux/amd64
2025-11-01 00:25:53.769256 | controller | ok: Runtime: 0:00:00.240167
2025-11-01 00:25:53.788031 | 
2025-11-01 00:25:53.788258 | TASK [ensure-podman : Print podman version installed]
2025-11-01 00:25:53.827586 | Podman version: Client:       Podman Engine
2025-11-01 00:25:53.827812 | Version:      4.6.2
2025-11-01 00:25:53.827845 | API Version:  4.6.2
2025-11-01 00:25:53.827869 | Go Version:   go1.19.12
2025-11-01 00:25:53.827891 | Built:        Mon Aug 28 19:38:31 2023
2025-11-01 00:25:53.827915 | OS/Arch:      linux/amd64
2025-11-01 00:25:53.835051 | 
2025-11-01 00:25:53.835137 | TASK [ensure-podman : Validate podman engine]
2025-11-01 00:25:53.973365 | controller | skipping: Conditional result was False
2025-11-01 00:25:53.981995 | 
2025-11-01 00:25:53.982098 | TASK [ensure-podman : Set up docker compatability socket]
2025-11-01 00:25:53.998417 | controller | skipping: Conditional result was False
2025-11-01 00:25:54.016526 | 
2025-11-01 00:25:54.016699 | TASK [Ensure python3.8 is present]
2025-11-01 00:25:54.042822 | controller | skipping: Conditional result was False
2025-11-01 00:25:54.052089 | 
2025-11-01 00:25:54.052214 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-11-01 00:25:54.075642 | controller | ok
2025-11-01 00:25:54.103109 | 
2025-11-01 00:25:54.103272 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-11-01 00:25:57.941007 | controller | ok: Nothing to do
2025-11-01 00:25:57.949267 | 
2025-11-01 00:25:57.949419 | TASK [our-ensure-python : Also install python3-devel]
2025-11-01 00:26:12.787535 | controller | changed
2025-11-01 00:26:12.812134 | 
2025-11-01 00:26:12.813213 | TASK [Run ensure-virtualenv role]
2025-11-01 00:26:12.845062 | controller | ok
2025-11-01 00:26:12.879170 | 
2025-11-01 00:26:12.879330 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-11-01 00:26:13.280298 | controller | /usr/bin/virtualenv
2025-11-01 00:26:13.524353 | controller | ok: Runtime: 0:00:00.004439
2025-11-01 00:26:13.537893 | 
2025-11-01 00:26:13.538077 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-11-01 00:26:13.575347 | controller | skipping: Conditional result was False
2025-11-01 00:26:13.575891 | controller | ok: All items complete
2025-11-01 00:26:13.575959 | 
2025-11-01 00:26:13.654281 | 
2025-11-01 00:26:13.654444 | TASK [Find the full path of the Python interpreter]
2025-11-01 00:26:14.112275 | controller | /usr/bin/python3
2025-11-01 00:26:14.290780 | controller | ok
2025-11-01 00:26:14.304267 | 
2025-11-01 00:26:14.304486 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-11-01 00:26:15.831438 | controller | created virtual environment CPython3.11.0.final.0-64 in 743ms
2025-11-01 00:26:15.873739 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-11-01 00:26:15.873795 | controller |   seeder FromAppData(extra_search_dir=/usr/share/python-wheels,download=False, pip=bundle, setuptools=bundle, wheel=bundle, via=copy, app_data_dir=/home/zuul-worker/.local/share/virtualenv)
2025-11-01 00:26:15.873813 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-11-01 00:26:15.873837 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-11-01 00:26:15.966616 | controller | changed
2025-11-01 00:26:15.979472 | 
2025-11-01 00:26:15.979624 | TASK [Set selinux package]
2025-11-01 00:26:16.021076 | controller | ok
2025-11-01 00:26:16.033537 | 
2025-11-01 00:26:16.033722 | TASK [Set selinux package (Fedora)]
2025-11-01 00:26:16.092707 | controller | ok
2025-11-01 00:26:16.100684 | 
2025-11-01 00:26:16.100806 | TASK [Install selinux into virtualenv]
2025-11-01 00:26:18.780316 | controller | Collecting selinux-please-lie-to-me
2025-11-01 00:26:18.868458 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-11-01 00:26:19.394796 | controller | Collecting setuptools<50.0.0
2025-11-01 00:26:19.408545 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-11-01 00:26:19.529795 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.8 MB/s eta 0:00:00
2025-11-01 00:26:19.682596 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-11-01 00:26:19.682895 | controller |   Attempting uninstall: setuptools
2025-11-01 00:26:19.687851 | controller |     Found existing installation: setuptools 62.6.0
2025-11-01 00:26:19.799900 | controller |     Uninstalling setuptools-62.6.0:
2025-11-01 00:26:19.814359 | controller |       Successfully uninstalled setuptools-62.6.0
2025-11-01 00:26:20.555077 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-11-01 00:26:20.759504 | controller |
2025-11-01 00:26:20.971911 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-01 00:26:20.971956 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-01 00:26:21.290801 | controller | ok: Runtime: 0:00:04.363550
2025-11-01 00:26:21.304514 | 
2025-11-01 00:26:21.304754 | TASK [Install pytest-forked into virtualenv]
2025-11-01 00:26:22.546396 | controller | Collecting pytest-forked
2025-11-01 00:26:22.630651 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-11-01 00:26:22.689907 | controller | Collecting py
2025-11-01 00:26:22.702752 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-11-01 00:26:22.735039 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.4 MB/s eta 0:00:00
2025-11-01 00:26:22.906578 | controller | Collecting pytest>=3.10
2025-11-01 00:26:22.920426 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-11-01 00:26:22.966312 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.3 MB/s eta 0:00:00
2025-11-01 00:26:23.018579 | controller | Collecting iniconfig>=1
2025-11-01 00:26:23.030868 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-11-01 00:26:23.094713 | controller | Collecting packaging>=20
2025-11-01 00:26:23.106708 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-11-01 00:26:23.116604 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 9.0 MB/s eta 0:00:00
2025-11-01 00:26:23.161208 | controller | Collecting pluggy<2,>=1.5
2025-11-01 00:26:23.173627 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-11-01 00:26:23.244732 | controller | Collecting pygments>=2.7.2
2025-11-01 00:26:23.256792 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-11-01 00:26:23.343716 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 14.6 MB/s eta 0:00:00
2025-11-01 00:26:23.478418 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-11-01 00:26:25.787093 | controller | Successfully installed iniconfig-2.3.0 packaging-25.0 pluggy-1.6.0 py-1.11.0 pygments-2.19.2 pytest-8.4.2 pytest-forked-1.6.0
2025-11-01 00:26:25.809300 | controller |
2025-11-01 00:26:26.023402 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-11-01 00:26:26.023449 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-11-01 00:26:26.499803 | controller | ok: Runtime: 0:00:04.209980
2025-11-01 00:26:26.511868 | 
2025-11-01 00:26:26.512002 | TASK [Update pip]
2025-11-01 00:26:27.683989 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-11-01 00:26:27.962145 | controller | Collecting pip
2025-11-01 00:26:28.062628 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-11-01 00:26:28.268777 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.8 MB/s eta 0:00:00
2025-11-01 00:26:28.392843 | controller | Installing collected packages: pip
2025-11-01 00:26:28.393307 | controller |   Attempting uninstall: pip
2025-11-01 00:26:28.397845 | controller |     Found existing installation: pip 22.2.2
2025-11-01 00:26:28.655384 | controller |     Uninstalling pip-22.2.2:
2025-11-01 00:26:28.708592 | controller |       Successfully uninstalled pip-22.2.2
2025-11-01 00:26:30.513159 | controller | Successfully installed pip-25.3
2025-11-01 00:26:31.191382 | controller | ok: Runtime: 0:00:03.637577
2025-11-01 00:26:31.201563 | 
2025-11-01 00:26:31.201778 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-11-01 00:26:31.745644 | controller | changed
2025-11-01 00:26:31.760212 | 
2025-11-01 00:26:31.760477 | TASK [Install ansible into virtualenv]
2025-11-01 00:26:32.911381 | controller | Processing ./src/github.com/ansible/ansible
2025-11-01 00:26:32.917616 | controller |   Installing build dependencies: started
2025-11-01 00:26:34.774553 | controller |   Installing build dependencies: finished with status 'done'
2025-11-01 00:26:36.359791 | controller |   Getting requirements to build wheel: started
2025-11-01 00:26:36.359849 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-11-01 00:26:36.365299 | controller |   Preparing metadata (pyproject.toml): started
2025-11-01 00:26:37.311283 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-11-01 00:26:37.311605 | controller | INFO: pip is looking at multiple versions of ansible-core to determine which version is compatible with other requirements. This could take a while.
2025-11-01 00:26:37.316448 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-11-01 00:26:37.916830 | controller | ERROR
2025-11-01 00:26:37.917131 | controller | {
2025-11-01 00:26:37.917162 | controller |   "delta": "0:00:05.246175",
2025-11-01 00:26:37.917181 | controller |   "end": "2025-11-01 00:26:37.468632",
2025-11-01 00:26:37.917198 | controller |   "msg": "non-zero return code",
2025-11-01 00:26:37.917240 | controller |   "rc": 1,
2025-11-01 00:26:37.917257 | controller |   "start": "2025-11-01 00:26:32.222457"
2025-11-01 00:26:37.917272 | controller | }
failure
2025-11-01 00:26:37.919654 | 
2025-11-01 00:26:37.919727 | PLAY RECAP
2025-11-01 00:26:37.919780 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-11-01 00:26:37.919800 | 
2025-11-01 00:26:38.117349 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-11-01 00:26:38.119895 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-01 00:26:38.797890 | 
2025-11-01 00:26:38.798084 | PLAY [all]
2025-11-01 00:26:38.820882 | 
2025-11-01 00:26:38.820972 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-11-01 00:26:39.649312 | controller | changed: non-zero return code
2025-11-01 00:26:39.662261 | 
2025-11-01 00:26:39.662471 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-11-01 00:26:39.692532 | controller | skipping: Conditional result was False
2025-11-01 00:26:39.707564 | 
2025-11-01 00:26:39.707758 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-11-01 00:26:39.753687 | 
2025-11-01 00:26:39.753964 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-11-01 00:26:39.797893 | 
2025-11-01 00:26:39.798219 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-11-01 00:26:39.827411 | controller | skipping: Conditional result was False
2025-11-01 00:26:39.847917 | 
2025-11-01 00:26:39.848105 | LOOP [fetch-subunit-output : Generate subunit file]
2025-11-01 00:26:39.890416 | 
2025-11-01 00:26:39.890652 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-11-01 00:26:39.917266 | controller | skipping: Conditional result was False
2025-11-01 00:26:39.928704 | 
2025-11-01 00:26:39.928869 | TASK [fetch-subunit-output : Remove the temporary file]
2025-11-01 00:26:39.956935 | controller | skipping: Conditional result was False
2025-11-01 00:26:39.967080 | 
2025-11-01 00:26:39.967196 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-11-01 00:26:39.993806 | controller | skipping: Conditional result was False
2025-11-01 00:26:40.025041 | 
2025-11-01 00:26:40.025231 | PLAY RECAP
2025-11-01 00:26:40.025280 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-11-01 00:26:40.025300 | 
2025-11-01 00:26:40.140266 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-11-01 00:26:40.142392 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-11-01 00:26:40.822469 | 
2025-11-01 00:26:40.822631 | PLAY [all:!appliance*]
2025-11-01 00:26:40.845979 | 
2025-11-01 00:26:40.846144 | TASK [unregister the node]
2025-11-01 00:26:40.982825 | controller | skipping: Conditional result was False
2025-11-01 00:26:40.990195 | 
2025-11-01 00:26:40.990386 | TASK [include_role : fetch-output]
2025-11-01 00:26:41.044502 | controller | ok
2025-11-01 00:26:41.074207 | 
2025-11-01 00:26:41.074381 | TASK [fetch-output : Set log path for multiple nodes]
2025-11-01 00:26:41.152832 | controller | skipping: Conditional result was False
2025-11-01 00:26:41.162729 | 
2025-11-01 00:26:41.162961 | TASK [fetch-output : Set log path for single node]
2025-11-01 00:26:41.215233 | controller | ok
2025-11-01 00:26:41.229731 | 
2025-11-01 00:26:41.229973 | LOOP [fetch-output : Ensure local output dirs]
2025-11-01 00:26:41.691855 | controller -> localhost | ok: "/var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/logs"
2025-11-01 00:26:42.040878 | controller -> localhost | changed: "/var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/artifacts"
2025-11-01 00:26:42.303731 | controller -> localhost | changed: "/var/lib/zuul/builds/190a877763804cc59fdb5db3e624ecc9/work/docs"
2025-11-01 00:26:42.319402 | 
2025-11-01 00:26:42.319484 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-11-01 00:26:43.714883 | controller | changed:
2025-11-01 00:26:43.715185 | controller | .d..t...... ./
2025-11-01 00:26:43.715226 | controller | cd+++++++++ controller/
2025-11-01 00:26:43.715276 | controller | changed: All items complete
2025-11-01 00:26:43.715307 | 
2025-11-01 00:26:44.865839 | controller | changed: .d..t...... ./
2025-11-01 00:26:45.911876 | controller | changed: .d..t...... ./
2025-11-01 00:26:45.942379 | 
2025-11-01 00:26:45.942607 | TASK [include_role : fetch-output-openshift]
2025-11-01 00:26:45.970748 | controller | skipping: Conditional result was False
2025-11-01 00:26:45.980093 | 
2025-11-01 00:26:45.980206 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-11-01 00:26:46.035040 | controller | skipping: Conditional result was False
2025-11-01 00:26:46.051210 | controller | skipping: Conditional result was False
2025-11-01 00:26:46.093981 | 
2025-11-01 00:26:46.094126 | PLAY [localhost]
2025-11-01 00:26:46.106991 | 
2025-11-01 00:26:46.107073 | TASK [Run Zuul manifest role]
2025-11-01 00:26:46.126394 | localhost | ok
2025-11-01 00:26:46.140762 | 
2025-11-01 00:26:46.140848 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-11-01 00:26:46.594623 | localhost | changed
2025-11-01 00:26:46.604654 | 
2025-11-01 00:26:46.604838 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-11-01 00:26:46.661901 | localhost | ok
2025-11-01 00:26:46.679922 | 
2025-11-01 00:26:46.680076 | TASK [Set zuul-log-path fact]
2025-11-01 00:26:46.707184 | localhost | ok
2025-11-01 00:26:46.731000 | 
2025-11-01 00:26:46.731088 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-11-01 00:26:46.763008 | localhost | ok
2025-11-01 00:26:46.775215 | 
2025-11-01 00:26:46.775297 | LOOP [Run upload-logs-swift role]
2025-11-01 00:26:46.821173 | localhost | Output suppressed because no_log was given
2025-11-01 00:26:46.855779 | 
2025-11-01 00:26:46.855869 | TASK [Set zuul-log-path fact]
2025-11-01 00:26:46.882464 | localhost | skipping: Conditional result was False
2025-11-01 00:26:46.889726 | 
2025-11-01 00:26:46.889812 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-11-01 00:26:47.347658 | localhost -> localhost | ok: Runtime: 0:00:00.009234
2025-11-01 00:26:47.360573 | 
2025-11-01 00:26:47.360745 | TASK [upload-logs-swift : Upload logs to swift]