2025-10-31 00:06:40.201641 | Job console starting...
2025-10-31 00:06:40.215306 | Updating repositories
2025-10-31 00:06:43.241671 | Preparing job workspace
2025-10-31 00:06:51.025664 | Running Ansible setup...
2025-10-31 00:06:56.933833 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-31 00:06:57.597327 | 
2025-10-31 00:06:57.597449 | PLAY [localhost]
2025-10-31 00:06:57.605944 | 
2025-10-31 00:06:57.606043 | TASK [Gathering Facts]
2025-10-31 00:06:58.676270 | localhost | ok
2025-10-31 00:06:58.703616 | 
2025-10-31 00:06:58.703759 | TASK [Setup log path fact]
2025-10-31 00:06:58.723087 | localhost | ok
2025-10-31 00:06:58.735684 | 
2025-10-31 00:06:58.735804 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-31 00:06:58.774614 | localhost | ok
2025-10-31 00:06:58.785747 | 
2025-10-31 00:06:58.785872 | TASK [emit-job-header : Print job information]
2025-10-31 00:06:58.837320 | # Job Information
2025-10-31 00:06:58.837527 | Ansible Version: 2.15.12
2025-10-31 00:06:58.837575 | Job: ansible-test-sanity-docker-milestone
2025-10-31 00:06:58.837606 | Pipeline: periodic
2025-10-31 00:06:58.837632 | Executor: ze01.softwarefactory-project.io
2025-10-31 00:06:58.837658 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-31 00:06:58.837691 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/d8c/ansible/d8cb7f83d82e4d92b405398ec8a0f447/
2025-10-31 00:06:58.837718 | Event ID: de96af6d0b7a45ea8c822badaf8296b2
2025-10-31 00:06:58.843360 | 
2025-10-31 00:06:58.843463 | LOOP [emit-job-header : Print node information]
2025-10-31 00:06:58.955091 | localhost | ok:
2025-10-31 00:06:58.955243 | localhost | # Node Information
2025-10-31 00:06:58.955270 | localhost | Inventory Hostname: controller
2025-10-31 00:06:58.955291 | localhost | Hostname: ip-172-16-118-162
2025-10-31 00:06:58.955310 | localhost | Username: zuul-worker
2025-10-31 00:06:58.955331 | localhost | Distro: Fedora 37
2025-10-31 00:06:58.955350 | localhost | Provider: ansible-us-east-2
2025-10-31 00:06:58.955367 | localhost | Region: us-east-2
2025-10-31 00:06:58.955384 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-31 00:06:58.955401 | localhost | Product Name: t3.small
2025-10-31 00:06:58.955418 | localhost | Interface IP: 18.225.36.224
2025-10-31 00:06:58.977141 | 
2025-10-31 00:06:58.977331 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-31 00:06:59.451588 | localhost -> localhost | changed
2025-10-31 00:06:59.457959 | 
2025-10-31 00:06:59.458117 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-31 00:07:00.397582 | localhost -> localhost | changed
2025-10-31 00:07:00.418347 | 
2025-10-31 00:07:00.418486 | PLAY [all:!appliance*]
2025-10-31 00:07:00.433764 | 
2025-10-31 00:07:00.433830 | TASK [include_role : start-zuul-console]
2025-10-31 00:07:00.454767 | controller | ok
2025-10-31 00:07:00.467407 | 
2025-10-31 00:07:00.467468 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-31 00:07:01.141907 | controller | ok
2025-10-31 00:07:01.177199 | 
2025-10-31 00:07:01.177562 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-31 00:07:03.509421 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-31 00:07:03.515851 | 
2025-10-31 00:07:03.515933 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-31 00:07:03.643706 | controller | skipping: Conditional result was False
2025-10-31 00:07:03.650167 | 
2025-10-31 00:07:03.650241 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-31 00:07:03.665106 | controller | skipping: Conditional result was False
2025-10-31 00:07:03.671722 | 
2025-10-31 00:07:03.671793 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-31 00:07:03.695814 | controller | skipping: Conditional result was False
2025-10-31 00:07:03.701744 | 
2025-10-31 00:07:03.701812 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-31 00:07:03.725824 | controller | skipping: Conditional result was False
2025-10-31 00:07:03.732095 | 
2025-10-31 00:07:03.732168 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-31 00:07:03.756721 | controller | skipping: Conditional result was False
2025-10-31 00:07:03.769685 | 
2025-10-31 00:07:03.769781 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-31 00:07:03.794533 | controller | skipping: Conditional result was False
2025-10-31 00:07:03.810130 | 
2025-10-31 00:07:03.810219 | TASK [Disable Fedora Modular]
2025-10-31 00:07:04.580831 | controller | changed
2025-10-31 00:07:04.586540 | 
2025-10-31 00:07:04.586606 | TASK [Enable EPEL]
2025-10-31 00:07:04.623328 | controller | skipping: Conditional result was False
2025-10-31 00:07:04.631543 | 
2025-10-31 00:07:04.631632 | TASK [Register the RHEL node]
2025-10-31 00:07:04.771375 | 
2025-10-31 00:07:04.771524 | TASK [Show the subscription-manager status]
2025-10-31 00:07:04.919707 | controller | skipping: Conditional result was False
2025-10-31 00:07:04.926132 | 
2025-10-31 00:07:04.926193 | TASK [Enable EPEL on RHEL]
2025-10-31 00:07:05.096379 | controller | skipping: Conditional result was False
2025-10-31 00:07:05.110504 | 
2025-10-31 00:07:05.110643 | TASK [Install git and tox]
2025-10-31 00:08:35.751966 | controller | changed
2025-10-31 00:08:35.764311 | 
2025-10-31 00:08:35.764416 | TASK [include_role : prepare-workspace]
2025-10-31 00:08:35.797839 | controller | ok
2025-10-31 00:08:35.834345 | 
2025-10-31 00:08:35.834485 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-31 00:08:36.367338 | controller | ok
2025-10-31 00:08:36.376431 | 
2025-10-31 00:08:36.376517 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-31 00:08:50.857226 | controller | Output suppressed because no_log was given
2025-10-31 00:08:50.870056 | 
2025-10-31 00:08:50.870161 | TASK [include_role : prepare-workspace-openshift]
2025-10-31 00:08:50.895526 | controller | skipping: Conditional result was False
2025-10-31 00:08:50.921411 | 
2025-10-31 00:08:50.921485 | PLAY [all:!appliance]
2025-10-31 00:08:50.977931 | 
2025-10-31 00:08:50.978056 | TASK [Run add-build-sshkey role (RSA)]
2025-10-31 00:08:51.009455 | controller | ok
2025-10-31 00:08:51.028570 | 
2025-10-31 00:08:51.028672 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-31 00:08:51.289975 | controller -> localhost | ok
2025-10-31 00:08:51.310626 | 
2025-10-31 00:08:51.310822 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-31 00:08:51.344828 | controller | ok
2025-10-31 00:08:51.367861 | controller | included: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-31 00:08:51.373951 | 
2025-10-31 00:08:51.374030 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-31 00:08:51.993960 | controller -> localhost | Generating public/private rsa key pair.
2025-10-31 00:08:51.994203 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/d8cb7f83d82e4d92b405398ec8a0f447_id_rsa.
2025-10-31 00:08:51.994233 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/d8cb7f83d82e4d92b405398ec8a0f447_id_rsa.pub.
2025-10-31 00:08:51.994256 | controller -> localhost | The key fingerprint is:
2025-10-31 00:08:51.994276 | controller -> localhost | SHA256:Zp8HnHny4oraFKtICY7oS+RUtWmHYCBYErK9K3s4VEo zuul-build-sshkey
2025-10-31 00:08:51.994296 | controller -> localhost | The key's randomart image is:
2025-10-31 00:08:51.994315 | controller -> localhost | +---[RSA 2048]----+
2025-10-31 00:08:51.994333 | controller -> localhost | |*+oo .           |
2025-10-31 00:08:51.994352 | controller -> localhost | |++. o +          |
2025-10-31 00:08:51.994371 | controller -> localhost | |. .. = .         |
2025-10-31 00:08:51.994389 | controller -> localhost | | E.o. .  . o     |
2025-10-31 00:08:51.994407 | controller -> localhost | |oo+   . S * .    |
2025-10-31 00:08:51.994433 | controller -> localhost | |B+ o   = . *     |
2025-10-31 00:08:51.994456 | controller -> localhost | |==+   o   + o    |
2025-10-31 00:08:51.994475 | controller -> localhost | |=+.. + . . o     |
2025-10-31 00:08:51.994494 | controller -> localhost | |.=o o.o ...      |
2025-10-31 00:08:51.994515 | controller -> localhost | +----[SHA256]-----+
2025-10-31 00:08:51.994562 | controller -> localhost | ok: Runtime: 0:00:00.176466
2025-10-31 00:08:52.001797 | 
2025-10-31 00:08:52.001889 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-31 00:08:52.037290 | controller | ok
2025-10-31 00:08:52.049929 | controller | included: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-31 00:08:52.060793 | 
2025-10-31 00:08:52.060913 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-31 00:08:52.086531 | controller | skipping: Conditional result was False
2025-10-31 00:08:52.092876 | 
2025-10-31 00:08:52.092983 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-31 00:08:52.819202 | controller | changed
2025-10-31 00:08:52.851234 | 
2025-10-31 00:08:52.851533 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-31 00:08:53.215968 | controller | ok
2025-10-31 00:08:53.229584 | 
2025-10-31 00:08:53.229710 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-31 00:08:54.504296 | controller | changed
2025-10-31 00:08:54.520824 | 
2025-10-31 00:08:54.520952 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-31 00:08:55.776210 | controller | changed
2025-10-31 00:08:55.791744 | 
2025-10-31 00:08:55.791917 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-31 00:08:55.819439 | controller | skipping: Conditional result was False
2025-10-31 00:08:55.831651 | 
2025-10-31 00:08:55.831977 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-31 00:08:56.270918 | controller -> localhost | changed
2025-10-31 00:08:56.283317 | 
2025-10-31 00:08:56.283403 | TASK [add-build-sshkey : Add back temp key]
2025-10-31 00:08:56.586051 | controller -> localhost | Identity added: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/d8cb7f83d82e4d92b405398ec8a0f447_id_rsa (zuul-build-sshkey)
2025-10-31 00:08:56.586346 | controller -> localhost | ok: Runtime: 0:00:00.016278
2025-10-31 00:08:56.595602 | 
2025-10-31 00:08:56.595705 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-31 00:08:57.131967 | controller | ok
2025-10-31 00:08:57.140508 | 
2025-10-31 00:08:57.140583 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-31 00:08:57.196205 | controller | skipping: Conditional result was False
2025-10-31 00:08:57.210861 | 
2025-10-31 00:08:57.210942 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-31 00:08:57.248541 | controller | ok
2025-10-31 00:08:57.264806 | 
2025-10-31 00:08:57.264875 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-31 00:08:57.525575 | controller -> localhost | ok
2025-10-31 00:08:57.532628 | 
2025-10-31 00:08:57.532710 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-31 00:08:57.570921 | controller | ok
2025-10-31 00:08:57.581802 | controller | included: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-31 00:08:57.588215 | 
2025-10-31 00:08:57.588275 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-31 00:08:57.889159 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-31 00:08:57.889642 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/d8cb7f83d82e4d92b405398ec8a0f447_id_ecdsa.
2025-10-31 00:08:57.889684 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/d8cb7f83d82e4d92b405398ec8a0f447_id_ecdsa.pub.
2025-10-31 00:08:57.889741 | controller -> localhost | The key fingerprint is:
2025-10-31 00:08:57.889771 | controller -> localhost | SHA256:JOQsootsskUp6cg4YW2wbTLVPT+57+rA0aIU30hzaCA zuul-build-sshkey
2025-10-31 00:08:57.889798 | controller -> localhost | The key's randomart image is:
2025-10-31 00:08:57.889824 | controller -> localhost | +---[ECDSA 521]---+
2025-10-31 00:08:57.889850 | controller -> localhost | |   E ..          |
2025-10-31 00:08:57.889875 | controller -> localhost | |    o+o .        |
2025-10-31 00:08:57.889900 | controller -> localhost | | ....o+B..       |
2025-10-31 00:08:57.889925 | controller -> localhost | | o*o .=oO .      |
2025-10-31 00:08:57.889950 | controller -> localhost | |==o= . =S*       |
2025-10-31 00:08:57.889974 | controller -> localhost | |O== . o o o      |
2025-10-31 00:08:57.889999 | controller -> localhost | |B=.  . o .       |
2025-10-31 00:08:57.890047 | controller -> localhost | |o+      . .      |
2025-10-31 00:08:57.890074 | controller -> localhost | |.       .ooo     |
2025-10-31 00:08:57.890098 | controller -> localhost | +----[SHA256]-----+
2025-10-31 00:08:57.890164 | controller -> localhost | ok: Runtime: 0:00:00.021036
2025-10-31 00:08:57.899858 | 
2025-10-31 00:08:57.899942 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-31 00:08:57.921453 | controller | ok
2025-10-31 00:08:57.929519 | controller | included: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-31 00:08:57.939184 | 
2025-10-31 00:08:57.939266 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-31 00:08:57.963974 | controller | skipping: Conditional result was False
2025-10-31 00:08:57.973313 | 
2025-10-31 00:08:57.973436 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-31 00:08:58.424734 | controller | changed
2025-10-31 00:08:58.441003 | 
2025-10-31 00:08:58.441192 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-31 00:08:58.789711 | controller | ok
2025-10-31 00:08:58.805288 | 
2025-10-31 00:08:58.805490 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-31 00:09:00.155852 | controller | changed
2025-10-31 00:09:00.161812 | 
2025-10-31 00:09:00.161889 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-31 00:09:01.756262 | controller | changed
2025-10-31 00:09:01.765432 | 
2025-10-31 00:09:01.765528 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-31 00:09:01.822047 | controller | skipping: Conditional result was False
2025-10-31 00:09:01.831893 | 
2025-10-31 00:09:01.832004 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-31 00:09:02.085260 | controller -> localhost | changed
2025-10-31 00:09:02.108662 | 
2025-10-31 00:09:02.108810 | TASK [add-build-sshkey : Add back temp key]
2025-10-31 00:09:02.411097 | controller -> localhost | Identity added: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/d8cb7f83d82e4d92b405398ec8a0f447_id_ecdsa (zuul-build-sshkey)
2025-10-31 00:09:02.411490 | controller -> localhost | ok: Runtime: 0:00:00.009169
2025-10-31 00:09:02.425993 | 
2025-10-31 00:09:02.426199 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-31 00:09:03.254379 | controller | ok
2025-10-31 00:09:03.302439 | 
2025-10-31 00:09:03.302618 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-31 00:09:03.338151 | controller | skipping: Conditional result was False
2025-10-31 00:09:03.361719 | 
2025-10-31 00:09:03.361850 | TASK [include_role : remove-zuul-sshkey]
2025-10-31 00:09:03.388922 | controller | skipping: Conditional result was False
2025-10-31 00:09:03.397567 | 
2025-10-31 00:09:03.397652 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-31 00:09:04.624457 | controller | ok: "logs"
2025-10-31 00:09:04.624700 | controller | ok: All items complete
2025-10-31 00:09:04.624728 | 
2025-10-31 00:09:04.982747 | controller | ok: "artifacts"
2025-10-31 00:09:05.297252 | controller | ok: "docs"
2025-10-31 00:09:05.321392 | 
2025-10-31 00:09:05.321655 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-31 00:09:05.658814 | controller | changed: "logs"
2025-10-31 00:09:05.930070 | controller | changed: "artifacts"
2025-10-31 00:09:06.213176 | controller | changed: "docs"
2025-10-31 00:09:06.257788 | 
2025-10-31 00:09:06.257899 | PLAY RECAP
2025-10-31 00:09:06.257960 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-31 00:09:06.257998 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-31 00:09:06.258051 | 
2025-10-31 00:09:06.404933 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-31 00:09:06.406714 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-31 00:09:07.167952 | 
2025-10-31 00:09:07.168103 | PLAY [all]
2025-10-31 00:09:07.191520 | 
2025-10-31 00:09:07.191629 | TASK [Install binary dependencies]
2025-10-31 00:09:07.261884 | controller | ok
2025-10-31 00:09:07.285990 | 
2025-10-31 00:09:07.286108 | TASK [bindep : Include find tasks]
2025-10-31 00:09:07.316322 | controller | ok
2025-10-31 00:09:07.324779 | controller | included: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-31 00:09:07.331126 | 
2025-10-31 00:09:07.331192 | TASK [bindep : Look for bindep.txt]
2025-10-31 00:09:07.835166 | controller | ok
2025-10-31 00:09:07.850676 | 
2025-10-31 00:09:07.850885 | TASK [bindep : Define bindep_file fact]
2025-10-31 00:09:07.878972 | controller | skipping: Conditional result was False
2025-10-31 00:09:07.887964 | 
2025-10-31 00:09:07.888280 | TASK [bindep : Look for other-requirements.txt]
2025-10-31 00:09:08.201176 | controller | ok
2025-10-31 00:09:08.214695 | 
2025-10-31 00:09:08.214855 | TASK [bindep : Define bindep_file fact]
2025-10-31 00:09:08.253162 | controller | skipping: Conditional result was False
2025-10-31 00:09:08.268434 | 
2025-10-31 00:09:08.268594 | TASK [bindep : Look for bindep fallback file]
2025-10-31 00:09:08.306713 | controller | skipping: Conditional result was False
2025-10-31 00:09:08.320688 | 
2025-10-31 00:09:08.320849 | TASK [bindep : Define bindep_file fact]
2025-10-31 00:09:08.350341 | controller | skipping: Conditional result was False
2025-10-31 00:09:08.360252 | 
2025-10-31 00:09:08.360389 | TASK [bindep : Include bindep tasks]
2025-10-31 00:09:08.395149 | controller | skipping: Conditional result was False
2025-10-31 00:09:08.405674 | 
2025-10-31 00:09:08.405823 | TASK [bindep : Include install tasks]
2025-10-31 00:09:08.431584 | controller | skipping: Conditional result was False
2025-10-31 00:09:08.440087 | 
2025-10-31 00:09:08.440191 | LOOP [bindep : Include package tasks]
2025-10-31 00:09:08.523464 | 
2025-10-31 00:09:08.523626 | TASK [Run test-setup role]
2025-10-31 00:09:08.545357 | controller | ok
2025-10-31 00:09:08.571737 | 
2025-10-31 00:09:08.571878 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-31 00:09:08.873526 | controller | ok
2025-10-31 00:09:08.886453 | 
2025-10-31 00:09:08.886624 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-31 00:09:09.047888 | controller | skipping: Conditional result was False
2025-10-31 00:09:09.105329 | 
2025-10-31 00:09:09.105491 | PLAY RECAP
2025-10-31 00:09:09.105555 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-31 00:09:09.105585 | 
2025-10-31 00:09:09.217836 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-31 00:09:09.220186 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-31 00:09:09.813759 | 
2025-10-31 00:09:09.813912 | PLAY [controller]
2025-10-31 00:09:09.835724 | 
2025-10-31 00:09:09.835884 | TASK [Create the /root directory]
2025-10-31 00:09:10.612219 | controller | ok
2025-10-31 00:09:10.625563 | 
2025-10-31 00:09:10.626060 | TASK [Install glibc-langpack-en]
2025-10-31 00:09:18.780529 | controller | ok: Nothing to do
2025-10-31 00:09:18.792930 | 
2025-10-31 00:09:18.793102 | TASK [Ensure controller directory exists]
2025-10-31 00:09:19.201285 | controller | changed
2025-10-31 00:09:19.215479 | 
2025-10-31 00:09:19.215704 | TASK [Install container runtime]
2025-10-31 00:09:19.294695 | controller | ok
2025-10-31 00:09:19.350358 | 
2025-10-31 00:09:19.350480 | LOOP [ensure-podman : Find distribution installation]
2025-10-31 00:09:19.389319 | controller | ok: "/var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-31 00:09:19.413981 | controller | included: /var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-31 00:09:19.429431 | 
2025-10-31 00:09:19.429572 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-31 00:10:39.826782 | controller | changed
2025-10-31 00:10:39.840828 | 
2025-10-31 00:10:39.840994 | TASK [ensure-podman : Fetch podman version]
2025-10-31 00:10:40.567165 | controller | Client:       Podman Engine
2025-10-31 00:10:40.567245 | controller | Version:      4.6.2
2025-10-31 00:10:40.567276 | controller | API Version:  4.6.2
2025-10-31 00:10:40.567308 | controller | Go Version:   go1.19.12
2025-10-31 00:10:40.567347 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-31 00:10:40.567376 | controller | OS/Arch:      linux/amd64
2025-10-31 00:10:40.996420 | controller | ok: Runtime: 0:00:00.229472
2025-10-31 00:10:41.009259 | 
2025-10-31 00:10:41.009395 | TASK [ensure-podman : Print podman version installed]
2025-10-31 00:10:41.048496 | Podman version: Client:       Podman Engine
2025-10-31 00:10:41.048745 | Version:      4.6.2
2025-10-31 00:10:41.048805 | API Version:  4.6.2
2025-10-31 00:10:41.048850 | Go Version:   go1.19.12
2025-10-31 00:10:41.048890 | Built:        Mon Aug 28 19:38:31 2023
2025-10-31 00:10:41.048931 | OS/Arch:      linux/amd64
2025-10-31 00:10:41.060369 | 
2025-10-31 00:10:41.060497 | TASK [ensure-podman : Validate podman engine]
2025-10-31 00:10:41.209350 | controller | skipping: Conditional result was False
2025-10-31 00:10:41.222066 | 
2025-10-31 00:10:41.222201 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-31 00:10:41.238761 | controller | skipping: Conditional result was False
2025-10-31 00:10:41.261604 | 
2025-10-31 00:10:41.261758 | TASK [Ensure python3.8 is present]
2025-10-31 00:10:41.277883 | controller | skipping: Conditional result was False
2025-10-31 00:10:41.290142 | 
2025-10-31 00:10:41.290276 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-31 00:10:41.317060 | controller | ok
2025-10-31 00:10:41.348886 | 
2025-10-31 00:10:41.349041 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-31 00:10:45.218725 | controller | ok: Nothing to do
2025-10-31 00:10:45.228438 | 
2025-10-31 00:10:45.228626 | TASK [our-ensure-python : Also install python3-devel]
2025-10-31 00:11:39.755937 | controller | changed
2025-10-31 00:11:39.772067 | 
2025-10-31 00:11:39.772252 | TASK [Run ensure-virtualenv role]
2025-10-31 00:11:39.801183 | controller | ok
2025-10-31 00:11:39.835303 | 
2025-10-31 00:11:39.835452 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-31 00:11:40.250839 | controller | /usr/bin/virtualenv
2025-10-31 00:11:40.478935 | controller | ok: Runtime: 0:00:00.005187
2025-10-31 00:11:40.493284 | 
2025-10-31 00:11:40.493441 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-31 00:11:40.524887 | controller | skipping: Conditional result was False
2025-10-31 00:11:40.525500 | controller | ok: All items complete
2025-10-31 00:11:40.525575 | 
2025-10-31 00:11:40.560612 | 
2025-10-31 00:11:40.560890 | TASK [Find the full path of the Python interpreter]
2025-10-31 00:11:41.099437 | controller | /usr/bin/python3
2025-10-31 00:11:41.302627 | controller | ok
2025-10-31 00:11:41.316786 | 
2025-10-31 00:11:41.316945 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-31 00:11:42.775458 | controller | created virtual environment CPython3.11.0.final.0-64 in 766ms
2025-10-31 00:11:42.817896 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-31 00:11:42.817954 | 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-10-31 00:11:42.817971 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-31 00:11:42.817996 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-31 00:11:42.973546 | controller | changed
2025-10-31 00:11:42.981377 | 
2025-10-31 00:11:42.981464 | TASK [Set selinux package]
2025-10-31 00:11:43.018363 | controller | ok
2025-10-31 00:11:43.029353 | 
2025-10-31 00:11:43.029483 | TASK [Set selinux package (Fedora)]
2025-10-31 00:11:43.089802 | controller | ok
2025-10-31 00:11:43.100690 | 
2025-10-31 00:11:43.100819 | TASK [Install selinux into virtualenv]
2025-10-31 00:11:45.750592 | controller | Collecting selinux-please-lie-to-me
2025-10-31 00:11:45.838218 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-31 00:11:46.371825 | controller | Collecting setuptools<50.0.0
2025-10-31 00:11:46.388919 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-31 00:11:46.518463 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.6 MB/s eta 0:00:00
2025-10-31 00:11:46.675224 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-31 00:11:46.675632 | controller |   Attempting uninstall: setuptools
2025-10-31 00:11:46.680733 | controller |     Found existing installation: setuptools 62.6.0
2025-10-31 00:11:46.792527 | controller |     Uninstalling setuptools-62.6.0:
2025-10-31 00:11:46.807271 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-31 00:11:47.553661 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-31 00:11:47.766380 | controller |
2025-10-31 00:11:47.983718 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-31 00:11:47.983772 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-31 00:11:48.299957 | controller | ok: Runtime: 0:00:04.400347
2025-10-31 00:11:48.311196 | 
2025-10-31 00:11:48.311460 | TASK [Install pytest-forked into virtualenv]
2025-10-31 00:11:49.528580 | controller | Collecting pytest-forked
2025-10-31 00:11:49.612977 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-31 00:11:49.672876 | controller | Collecting py
2025-10-31 00:11:49.685034 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-31 00:11:49.717172 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.8 MB/s eta 0:00:00
2025-10-31 00:11:49.890469 | controller | Collecting pytest>=3.10
2025-10-31 00:11:49.902476 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-31 00:11:49.949725 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 8.3 MB/s eta 0:00:00
2025-10-31 00:11:50.007533 | controller | Collecting iniconfig>=1
2025-10-31 00:11:50.019798 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-31 00:11:50.087709 | controller | Collecting packaging>=20
2025-10-31 00:11:50.099455 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-31 00:11:50.109829 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.6 MB/s eta 0:00:00
2025-10-31 00:11:50.155359 | controller | Collecting pluggy<2,>=1.5
2025-10-31 00:11:50.168994 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-31 00:11:50.244933 | controller | Collecting pygments>=2.7.2
2025-10-31 00:11:50.256586 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-31 00:11:50.348100 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.8 MB/s eta 0:00:00
2025-10-31 00:11:50.477272 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-31 00:11:52.685107 | 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-10-31 00:11:52.701208 | controller |
2025-10-31 00:11:52.888981 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-31 00:11:52.889024 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-31 00:11:53.011388 | controller | ok: Runtime: 0:00:04.088970
2025-10-31 00:11:53.023623 | 
2025-10-31 00:11:53.023755 | TASK [Update pip]
2025-10-31 00:11:54.158312 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-31 00:11:54.452933 | controller | Collecting pip
2025-10-31 00:11:54.552421 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-31 00:11:54.714433 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 11.3 MB/s eta 0:00:00
2025-10-31 00:11:54.879619 | controller | Installing collected packages: pip
2025-10-31 00:11:54.879952 | controller |   Attempting uninstall: pip
2025-10-31 00:11:54.885793 | controller |     Found existing installation: pip 22.2.2
2025-10-31 00:11:55.153584 | controller |     Uninstalling pip-22.2.2:
2025-10-31 00:11:55.183272 | controller |       Successfully uninstalled pip-22.2.2
2025-10-31 00:11:56.945035 | controller | Successfully installed pip-25.3
2025-10-31 00:11:57.679612 | controller | ok: Runtime: 0:00:03.582766
2025-10-31 00:11:57.685451 | 
2025-10-31 00:11:57.685513 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-31 00:11:58.201581 | controller | changed
2025-10-31 00:11:58.213905 | 
2025-10-31 00:11:58.214109 | TASK [Install ansible into virtualenv]
2025-10-31 00:11:59.289884 | controller | Processing ./src/github.com/ansible/ansible
2025-10-31 00:11:59.296361 | controller |   Installing build dependencies: started
2025-10-31 00:12:01.320837 | controller |   Installing build dependencies: finished with status 'done'
2025-10-31 00:12:01.321983 | controller |   Getting requirements to build wheel: started
2025-10-31 00:12:02.904394 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-31 00:12:02.905848 | controller |   Preparing metadata (pyproject.toml): started
2025-10-31 00:12:03.884867 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-31 00:12:03.887926 | 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-10-31 00:12:03.892832 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-31 00:12:04.392256 | controller | ERROR
2025-10-31 00:12:04.392559 | controller | {
2025-10-31 00:12:04.392624 | controller |   "delta": "0:00:05.415703",
2025-10-31 00:12:04.392670 | controller |   "end": "2025-10-31 00:12:04.051567",
2025-10-31 00:12:04.392709 | controller |   "msg": "non-zero return code",
2025-10-31 00:12:04.392763 | controller |   "rc": 1,
2025-10-31 00:12:04.392802 | controller |   "start": "2025-10-31 00:11:58.635864"
2025-10-31 00:12:04.392841 | controller | }
failure
2025-10-31 00:12:04.395592 | 
2025-10-31 00:12:04.395696 | PLAY RECAP
2025-10-31 00:12:04.395785 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-31 00:12:04.395832 | 
2025-10-31 00:12:04.534419 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-31 00:12:04.535388 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-31 00:12:05.145614 | 
2025-10-31 00:12:05.145723 | PLAY [all]
2025-10-31 00:12:05.174828 | 
2025-10-31 00:12:05.174943 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-31 00:12:05.941156 | controller | changed: non-zero return code
2025-10-31 00:12:05.948334 | 
2025-10-31 00:12:05.948458 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-31 00:12:05.964819 | controller | skipping: Conditional result was False
2025-10-31 00:12:05.971469 | 
2025-10-31 00:12:05.971546 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-31 00:12:06.007005 | 
2025-10-31 00:12:06.007176 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-31 00:12:06.047547 | 
2025-10-31 00:12:06.047700 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-31 00:12:06.071923 | controller | skipping: Conditional result was False
2025-10-31 00:12:06.079046 | 
2025-10-31 00:12:06.079177 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-31 00:12:06.103613 | 
2025-10-31 00:12:06.103930 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-31 00:12:06.124099 | controller | skipping: Conditional result was False
2025-10-31 00:12:06.133945 | 
2025-10-31 00:12:06.134053 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-31 00:12:06.149885 | controller | skipping: Conditional result was False
2025-10-31 00:12:06.157106 | 
2025-10-31 00:12:06.157173 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-31 00:12:06.172007 | controller | skipping: Conditional result was False
2025-10-31 00:12:06.196397 | 
2025-10-31 00:12:06.196465 | PLAY RECAP
2025-10-31 00:12:06.196505 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-31 00:12:06.196525 | 
2025-10-31 00:12:06.303980 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-31 00:12:06.304854 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-31 00:12:06.897528 | 
2025-10-31 00:12:06.897652 | PLAY [all:!appliance*]
2025-10-31 00:12:06.929117 | 
2025-10-31 00:12:06.929220 | TASK [unregister the node]
2025-10-31 00:12:07.062628 | controller | skipping: Conditional result was False
2025-10-31 00:12:07.074604 | 
2025-10-31 00:12:07.074821 | TASK [include_role : fetch-output]
2025-10-31 00:12:07.125184 | controller | ok
2025-10-31 00:12:07.153394 | 
2025-10-31 00:12:07.153501 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-31 00:12:07.199464 | controller | skipping: Conditional result was False
2025-10-31 00:12:07.213177 | 
2025-10-31 00:12:07.213333 | TASK [fetch-output : Set log path for single node]
2025-10-31 00:12:07.250586 | controller | ok
2025-10-31 00:12:07.259231 | 
2025-10-31 00:12:07.259325 | LOOP [fetch-output : Ensure local output dirs]
2025-10-31 00:12:07.640202 | controller -> localhost | ok: "/var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/logs"
2025-10-31 00:12:07.885208 | controller -> localhost | changed: "/var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/artifacts"
2025-10-31 00:12:08.128060 | controller -> localhost | changed: "/var/lib/zuul/builds/d8cb7f83d82e4d92b405398ec8a0f447/work/docs"
2025-10-31 00:12:08.140672 | 
2025-10-31 00:12:08.140798 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-31 00:12:09.385768 | controller | changed:
2025-10-31 00:12:09.385991 | controller | .d..t...... ./
2025-10-31 00:12:09.386041 | controller | cd+++++++++ controller/
2025-10-31 00:12:09.386077 | controller | changed: All items complete
2025-10-31 00:12:09.386098 | 
2025-10-31 00:12:11.062612 | controller | changed: .d..t...... ./
2025-10-31 00:12:12.147283 | controller | changed: .d..t...... ./
2025-10-31 00:12:12.164138 | 
2025-10-31 00:12:12.164246 | TASK [include_role : fetch-output-openshift]
2025-10-31 00:12:12.188712 | controller | skipping: Conditional result was False
2025-10-31 00:12:12.194868 | 
2025-10-31 00:12:12.194943 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-31 00:12:12.232955 | controller | skipping: Conditional result was False
2025-10-31 00:12:12.233761 | controller | skipping: Conditional result was False
2025-10-31 00:12:12.265776 | 
2025-10-31 00:12:12.265869 | PLAY [localhost]
2025-10-31 00:12:12.277755 | 
2025-10-31 00:12:12.277826 | TASK [Run Zuul manifest role]
2025-10-31 00:12:12.295776 | localhost | ok
2025-10-31 00:12:12.311101 | 
2025-10-31 00:12:12.311236 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-31 00:12:12.660836 | localhost | changed
2025-10-31 00:12:12.675703 | 
2025-10-31 00:12:12.675800 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-31 00:12:12.714374 | localhost | ok
2025-10-31 00:12:12.722388 | 
2025-10-31 00:12:12.722470 | TASK [Set zuul-log-path fact]
2025-10-31 00:12:12.740875 | localhost | ok
2025-10-31 00:12:12.754997 | 
2025-10-31 00:12:12.755119 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-31 00:12:12.785233 | localhost | ok
2025-10-31 00:12:12.793449 | 
2025-10-31 00:12:12.793555 | LOOP [Run upload-logs-swift role]
2025-10-31 00:12:12.828909 | localhost | Output suppressed because no_log was given
2025-10-31 00:12:12.857298 | 
2025-10-31 00:12:12.857414 | TASK [Set zuul-log-path fact]
2025-10-31 00:12:12.891765 | localhost | skipping: Conditional result was False
2025-10-31 00:12:12.897453 | 
2025-10-31 00:12:12.897526 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-31 00:12:13.297263 | localhost -> localhost | ok: Runtime: 0:00:00.008225
2025-10-31 00:12:13.304197 | 
2025-10-31 00:12:13.304283 | TASK [upload-logs-swift : Upload logs to swift]