2025-10-30 00:06:41.846836 | Job console starting...
2025-10-30 00:06:41.853754 | Updating repositories
2025-10-30 00:06:43.666872 | Preparing job workspace
2025-10-30 00:06:56.842797 | Running Ansible setup...
2025-10-30 00:07:04.230666 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-30 00:07:04.886624 | 
2025-10-30 00:07:04.886754 | PLAY [localhost]
2025-10-30 00:07:04.895421 | 
2025-10-30 00:07:04.895551 | TASK [Gathering Facts]
2025-10-30 00:07:05.907083 | localhost | ok
2025-10-30 00:07:05.935170 | 
2025-10-30 00:07:05.935328 | TASK [Setup log path fact]
2025-10-30 00:07:05.956496 | localhost | ok
2025-10-30 00:07:05.975135 | 
2025-10-30 00:07:05.975267 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-30 00:07:06.006241 | localhost | ok
2025-10-30 00:07:06.017532 | 
2025-10-30 00:07:06.017635 | TASK [emit-job-header : Print job information]
2025-10-30 00:07:06.061672 | # Job Information
2025-10-30 00:07:06.061916 | Ansible Version: 2.15.12
2025-10-30 00:07:06.061983 | Job: ansible-test-sanity-docker-devel
2025-10-30 00:07:06.062069 | Pipeline: periodic
2025-10-30 00:07:06.062115 | Executor: ze01.softwarefactory-project.io
2025-10-30 00:07:06.062155 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-30 00:07:06.062201 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/fa4/ansible/fa4f7840e9364593a14dce4e299273a7/
2025-10-30 00:07:06.062243 | Event ID: 3d3b3e11113e4aa4883722e12166235f
2025-10-30 00:07:06.071008 | 
2025-10-30 00:07:06.071201 | LOOP [emit-job-header : Print node information]
2025-10-30 00:07:06.178007 | localhost | ok:
2025-10-30 00:07:06.178285 | localhost | # Node Information
2025-10-30 00:07:06.178314 | localhost | Inventory Hostname: controller
2025-10-30 00:07:06.178334 | localhost | Hostname: ip-172-16-157-187
2025-10-30 00:07:06.178353 | localhost | Username: zuul-worker
2025-10-30 00:07:06.178373 | localhost | Distro: Fedora 37
2025-10-30 00:07:06.178392 | localhost | Provider: ansible-us-east-2
2025-10-30 00:07:06.178408 | localhost | Region: us-east-2
2025-10-30 00:07:06.178424 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-30 00:07:06.178440 | localhost | Product Name: t3.small
2025-10-30 00:07:06.178456 | localhost | Interface IP: 3.19.57.138
2025-10-30 00:07:06.192677 | 
2025-10-30 00:07:06.192816 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-30 00:07:06.678893 | localhost -> localhost | changed
2025-10-30 00:07:06.684760 | 
2025-10-30 00:07:06.684829 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-30 00:07:07.613298 | localhost -> localhost | changed
2025-10-30 00:07:07.637061 | 
2025-10-30 00:07:07.637139 | PLAY [all:!appliance*]
2025-10-30 00:07:07.657464 | 
2025-10-30 00:07:07.657590 | TASK [include_role : start-zuul-console]
2025-10-30 00:07:07.677993 | controller | ok
2025-10-30 00:07:07.695244 | 
2025-10-30 00:07:07.695409 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-30 00:07:08.307579 | controller | ok
2025-10-30 00:07:08.320127 | 
2025-10-30 00:07:08.320237 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-30 00:07:09.973656 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-30 00:07:09.986611 | 
2025-10-30 00:07:09.986759 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-30 00:07:10.137350 | controller | skipping: Conditional result was False
2025-10-30 00:07:10.159389 | 
2025-10-30 00:07:10.159569 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-30 00:07:10.185622 | controller | skipping: Conditional result was False
2025-10-30 00:07:10.200643 | 
2025-10-30 00:07:10.200834 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-30 00:07:10.226459 | controller | skipping: Conditional result was False
2025-10-30 00:07:10.235191 | 
2025-10-30 00:07:10.235297 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-30 00:07:10.269800 | controller | skipping: Conditional result was False
2025-10-30 00:07:10.282421 | 
2025-10-30 00:07:10.282537 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-30 00:07:10.307142 | controller | skipping: Conditional result was False
2025-10-30 00:07:10.317095 | 
2025-10-30 00:07:10.317184 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-30 00:07:10.343097 | controller | skipping: Conditional result was False
2025-10-30 00:07:10.358455 | 
2025-10-30 00:07:10.358597 | TASK [Disable Fedora Modular]
2025-10-30 00:07:11.176713 | controller | changed
2025-10-30 00:07:11.190643 | 
2025-10-30 00:07:11.190764 | TASK [Enable EPEL]
2025-10-30 00:07:11.218399 | controller | skipping: Conditional result was False
2025-10-30 00:07:11.226497 | 
2025-10-30 00:07:11.226590 | TASK [Register the RHEL node]
2025-10-30 00:07:11.373322 | 
2025-10-30 00:07:11.373482 | TASK [Show the subscription-manager status]
2025-10-30 00:07:11.518946 | controller | skipping: Conditional result was False
2025-10-30 00:07:11.550838 | 
2025-10-30 00:07:11.550948 | TASK [Enable EPEL on RHEL]
2025-10-30 00:07:11.691895 | controller | skipping: Conditional result was False
2025-10-30 00:07:11.698058 | 
2025-10-30 00:07:11.698191 | TASK [Install git and tox]
2025-10-30 00:08:30.978558 | controller | changed
2025-10-30 00:08:30.992609 | 
2025-10-30 00:08:30.992760 | TASK [include_role : prepare-workspace]
2025-10-30 00:08:31.022102 | controller | ok
2025-10-30 00:08:31.064899 | 
2025-10-30 00:08:31.065052 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-30 00:08:31.591336 | controller | ok
2025-10-30 00:08:31.613624 | 
2025-10-30 00:08:31.613814 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-30 00:08:50.258068 | controller | Output suppressed because no_log was given
2025-10-30 00:08:50.270185 | 
2025-10-30 00:08:50.270280 | TASK [include_role : prepare-workspace-openshift]
2025-10-30 00:08:50.297805 | controller | skipping: Conditional result was False
2025-10-30 00:08:50.322744 | 
2025-10-30 00:08:50.322825 | PLAY [all:!appliance]
2025-10-30 00:08:50.338618 | 
2025-10-30 00:08:50.338716 | TASK [Run add-build-sshkey role (RSA)]
2025-10-30 00:08:50.359672 | controller | ok
2025-10-30 00:08:50.414976 | 
2025-10-30 00:08:50.415159 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-30 00:08:50.633472 | controller -> localhost | ok
2025-10-30 00:08:50.639615 | 
2025-10-30 00:08:50.639686 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-30 00:08:50.659626 | controller | ok
2025-10-30 00:08:50.678944 | controller | included: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-30 00:08:50.685375 | 
2025-10-30 00:08:50.685444 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-30 00:08:51.203854 | controller -> localhost | Generating public/private rsa key pair.
2025-10-30 00:08:51.204076 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/fa4f7840e9364593a14dce4e299273a7_id_rsa.
2025-10-30 00:08:51.204106 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/fa4f7840e9364593a14dce4e299273a7_id_rsa.pub.
2025-10-30 00:08:51.204127 | controller -> localhost | The key fingerprint is:
2025-10-30 00:08:51.204147 | controller -> localhost | SHA256:NMJD3zDSJisok/+acr9piKJhgLnyqEgkBJe9tRj1AMI zuul-build-sshkey
2025-10-30 00:08:51.204167 | controller -> localhost | The key's randomart image is:
2025-10-30 00:08:51.204186 | controller -> localhost | +---[RSA 2048]----+
2025-10-30 00:08:51.204205 | controller -> localhost | |..oo.o=.o        |
2025-10-30 00:08:51.204223 | controller -> localhost | |..E.ooo=o+       |
2025-10-30 00:08:51.204242 | controller -> localhost | | o . =+== .      |
2025-10-30 00:08:51.204260 | controller -> localhost | |*.. + o+ .       |
2025-10-30 00:08:51.204278 | controller -> localhost | |==   .  S        |
2025-10-30 00:08:51.204307 | controller -> localhost | |+..              |
2025-10-30 00:08:51.204330 | controller -> localhost | |++ o             |
2025-10-30 00:08:51.204349 | controller -> localhost | |O+o.o.           |
2025-10-30 00:08:51.204367 | controller -> localhost | |Oo+++.           |
2025-10-30 00:08:51.204387 | controller -> localhost | +----[SHA256]-----+
2025-10-30 00:08:51.204435 | controller -> localhost | ok: Runtime: 0:00:00.151669
2025-10-30 00:08:51.210311 | 
2025-10-30 00:08:51.210377 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-30 00:08:51.267052 | controller | ok
2025-10-30 00:08:51.284174 | controller | included: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-30 00:08:51.301613 | 
2025-10-30 00:08:51.301723 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-30 00:08:51.331129 | controller | skipping: Conditional result was False
2025-10-30 00:08:51.338359 | 
2025-10-30 00:08:51.338443 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-30 00:08:51.954699 | controller | changed
2025-10-30 00:08:51.965863 | 
2025-10-30 00:08:51.965972 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-30 00:08:52.342250 | controller | ok
2025-10-30 00:08:52.362800 | 
2025-10-30 00:08:52.362948 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-30 00:08:53.815781 | controller | changed
2025-10-30 00:08:53.831759 | 
2025-10-30 00:08:53.832072 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-30 00:08:55.209790 | controller | changed
2025-10-30 00:08:55.216089 | 
2025-10-30 00:08:55.216184 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-30 00:08:55.240707 | controller | skipping: Conditional result was False
2025-10-30 00:08:55.247440 | 
2025-10-30 00:08:55.247516 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-30 00:08:55.607304 | controller -> localhost | changed
2025-10-30 00:08:55.624182 | 
2025-10-30 00:08:55.624334 | TASK [add-build-sshkey : Add back temp key]
2025-10-30 00:08:55.914366 | controller -> localhost | Identity added: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/fa4f7840e9364593a14dce4e299273a7_id_rsa (zuul-build-sshkey)
2025-10-30 00:08:55.914595 | controller -> localhost | ok: Runtime: 0:00:00.008780
2025-10-30 00:08:55.921151 | 
2025-10-30 00:08:55.921231 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-30 00:08:56.476083 | controller | ok
2025-10-30 00:08:56.484452 | 
2025-10-30 00:08:56.484580 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-30 00:08:56.530044 | controller | skipping: Conditional result was False
2025-10-30 00:08:56.541471 | 
2025-10-30 00:08:56.541540 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-30 00:08:56.571333 | controller | ok
2025-10-30 00:08:56.587254 | 
2025-10-30 00:08:56.587334 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-30 00:08:56.888278 | controller -> localhost | ok
2025-10-30 00:08:56.895159 | 
2025-10-30 00:08:56.895264 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-30 00:08:56.940132 | controller | ok
2025-10-30 00:08:56.954062 | controller | included: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-30 00:08:56.961985 | 
2025-10-30 00:08:56.962112 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-30 00:08:57.329239 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-30 00:08:57.329471 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/fa4f7840e9364593a14dce4e299273a7_id_ecdsa.
2025-10-30 00:08:57.329500 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/fa4f7840e9364593a14dce4e299273a7_id_ecdsa.pub.
2025-10-30 00:08:57.329528 | controller -> localhost | The key fingerprint is:
2025-10-30 00:08:57.329549 | controller -> localhost | SHA256:e4A2TgIYMFLRzsoS7InRN/nIQ1jRcdKMysSYVNTdgqs zuul-build-sshkey
2025-10-30 00:08:57.329567 | controller -> localhost | The key's randomart image is:
2025-10-30 00:08:57.329585 | controller -> localhost | +---[ECDSA 521]---+
2025-10-30 00:08:57.329603 | controller -> localhost | |*o+O++oB..       |
2025-10-30 00:08:57.329620 | controller -> localhost | |.+o = =o= .      |
2025-10-30 00:08:57.329636 | controller -> localhost | |o..B o . .       |
2025-10-30 00:08:57.329652 | controller -> localhost | |o.o.X ..         |
2025-10-30 00:08:57.329668 | controller -> localhost | |o+.=.== S        |
2025-10-30 00:08:57.329685 | controller -> localhost | |ooo E=.. o       |
2025-10-30 00:08:57.329701 | controller -> localhost | | .   .. . .      |
2025-10-30 00:08:57.329717 | controller -> localhost | |         .       |
2025-10-30 00:08:57.329734 | controller -> localhost | |                 |
2025-10-30 00:08:57.329750 | controller -> localhost | +----[SHA256]-----+
2025-10-30 00:08:57.329801 | controller -> localhost | ok: Runtime: 0:00:00.025216
2025-10-30 00:08:57.336871 | 
2025-10-30 00:08:57.336942 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-30 00:08:57.368319 | controller | ok
2025-10-30 00:08:57.376873 | controller | included: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-30 00:08:57.385771 | 
2025-10-30 00:08:57.385844 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-30 00:08:57.413056 | controller | skipping: Conditional result was False
2025-10-30 00:08:57.423445 | 
2025-10-30 00:08:57.423567 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-30 00:08:57.879470 | controller | changed
2025-10-30 00:08:57.887363 | 
2025-10-30 00:08:57.887474 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-30 00:08:58.263917 | controller | ok
2025-10-30 00:08:58.270558 | 
2025-10-30 00:08:58.270631 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-30 00:08:59.616899 | controller | changed
2025-10-30 00:08:59.626230 | 
2025-10-30 00:08:59.626385 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-30 00:09:01.204323 | controller | changed
2025-10-30 00:09:01.212967 | 
2025-10-30 00:09:01.213125 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-30 00:09:01.249230 | controller | skipping: Conditional result was False
2025-10-30 00:09:01.261299 | 
2025-10-30 00:09:01.261429 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-30 00:09:01.545174 | controller -> localhost | changed
2025-10-30 00:09:01.570547 | 
2025-10-30 00:09:01.570683 | TASK [add-build-sshkey : Add back temp key]
2025-10-30 00:09:01.839931 | controller -> localhost | Identity added: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/fa4f7840e9364593a14dce4e299273a7_id_ecdsa (zuul-build-sshkey)
2025-10-30 00:09:01.840234 | controller -> localhost | ok: Runtime: 0:00:00.008292
2025-10-30 00:09:01.849101 | 
2025-10-30 00:09:01.849225 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-30 00:09:02.460694 | controller | ok
2025-10-30 00:09:02.475102 | 
2025-10-30 00:09:02.475275 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-30 00:09:02.514574 | controller | skipping: Conditional result was False
2025-10-30 00:09:02.532768 | 
2025-10-30 00:09:02.532912 | TASK [include_role : remove-zuul-sshkey]
2025-10-30 00:09:02.558549 | controller | skipping: Conditional result was False
2025-10-30 00:09:02.568901 | 
2025-10-30 00:09:02.569080 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-30 00:09:03.105860 | controller | ok: "logs"
2025-10-30 00:09:03.106082 | controller | ok: All items complete
2025-10-30 00:09:03.106113 | 
2025-10-30 00:09:03.668549 | controller | ok: "artifacts"
2025-10-30 00:09:04.003838 | controller | ok: "docs"
2025-10-30 00:09:04.026834 | 
2025-10-30 00:09:04.026970 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-30 00:09:04.388187 | controller | changed: "logs"
2025-10-30 00:09:05.534420 | controller | changed: "artifacts"
2025-10-30 00:09:05.938482 | controller | changed: "docs"
2025-10-30 00:09:06.012229 | 
2025-10-30 00:09:06.012379 | PLAY RECAP
2025-10-30 00:09:06.012469 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-30 00:09:06.012525 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-30 00:09:06.012577 | 
2025-10-30 00:09:06.165181 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-30 00:09:06.166830 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-30 00:09:06.766967 | 
2025-10-30 00:09:06.767132 | PLAY [all]
2025-10-30 00:09:06.791175 | 
2025-10-30 00:09:06.791310 | TASK [Install binary dependencies]
2025-10-30 00:09:06.843473 | controller | ok
2025-10-30 00:09:06.867702 | 
2025-10-30 00:09:06.867852 | TASK [bindep : Include find tasks]
2025-10-30 00:09:06.897910 | controller | ok
2025-10-30 00:09:06.906753 | controller | included: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-30 00:09:06.912883 | 
2025-10-30 00:09:06.912948 | TASK [bindep : Look for bindep.txt]
2025-10-30 00:09:07.447999 | controller | ok
2025-10-30 00:09:07.463157 | 
2025-10-30 00:09:07.463321 | TASK [bindep : Define bindep_file fact]
2025-10-30 00:09:07.489312 | controller | skipping: Conditional result was False
2025-10-30 00:09:07.497398 | 
2025-10-30 00:09:07.497550 | TASK [bindep : Look for other-requirements.txt]
2025-10-30 00:09:07.842802 | controller | ok
2025-10-30 00:09:07.861956 | 
2025-10-30 00:09:07.862261 | TASK [bindep : Define bindep_file fact]
2025-10-30 00:09:07.888368 | controller | skipping: Conditional result was False
2025-10-30 00:09:07.904347 | 
2025-10-30 00:09:07.904542 | TASK [bindep : Look for bindep fallback file]
2025-10-30 00:09:07.941695 | controller | skipping: Conditional result was False
2025-10-30 00:09:07.955699 | 
2025-10-30 00:09:07.955901 | TASK [bindep : Define bindep_file fact]
2025-10-30 00:09:07.983456 | controller | skipping: Conditional result was False
2025-10-30 00:09:07.993388 | 
2025-10-30 00:09:07.993532 | TASK [bindep : Include bindep tasks]
2025-10-30 00:09:08.028863 | controller | skipping: Conditional result was False
2025-10-30 00:09:08.040030 | 
2025-10-30 00:09:08.040184 | TASK [bindep : Include install tasks]
2025-10-30 00:09:08.064998 | controller | skipping: Conditional result was False
2025-10-30 00:09:08.075214 | 
2025-10-30 00:09:08.075384 | LOOP [bindep : Include package tasks]
2025-10-30 00:09:08.148518 | 
2025-10-30 00:09:08.148736 | TASK [Run test-setup role]
2025-10-30 00:09:08.175109 | controller | ok
2025-10-30 00:09:08.205825 | 
2025-10-30 00:09:08.205976 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-30 00:09:08.548906 | controller | ok
2025-10-30 00:09:08.563499 | 
2025-10-30 00:09:08.563648 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-30 00:09:08.720741 | controller | skipping: Conditional result was False
2025-10-30 00:09:08.756838 | 
2025-10-30 00:09:08.756946 | PLAY RECAP
2025-10-30 00:09:08.757001 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-30 00:09:08.757055 | 
2025-10-30 00:09:08.896790 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-30 00:09:08.897781 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-30 00:09:09.528740 | 
2025-10-30 00:09:09.528878 | PLAY [controller]
2025-10-30 00:09:09.549299 | 
2025-10-30 00:09:09.549416 | TASK [Create the /root directory]
2025-10-30 00:09:10.302326 | controller | ok
2025-10-30 00:09:10.322371 | 
2025-10-30 00:09:10.322521 | TASK [Install glibc-langpack-en]
2025-10-30 00:09:18.443533 | controller | ok: Nothing to do
2025-10-30 00:09:18.449698 | 
2025-10-30 00:09:18.449771 | TASK [Ensure controller directory exists]
2025-10-30 00:09:18.915687 | controller | changed
2025-10-30 00:09:18.927732 | 
2025-10-30 00:09:18.927853 | TASK [Install container runtime]
2025-10-30 00:09:18.989001 | controller | ok
2025-10-30 00:09:19.036793 | 
2025-10-30 00:09:19.036927 | LOOP [ensure-podman : Find distribution installation]
2025-10-30 00:09:19.081289 | controller | ok: "/var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-30 00:09:19.095871 | controller | included: /var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-30 00:09:19.104255 | 
2025-10-30 00:09:19.104403 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-30 00:10:34.243950 | controller | changed
2025-10-30 00:10:34.266465 | 
2025-10-30 00:10:34.266604 | TASK [ensure-podman : Fetch podman version]
2025-10-30 00:10:35.086871 | controller | Client:       Podman Engine
2025-10-30 00:10:35.086950 | controller | Version:      4.6.2
2025-10-30 00:10:35.086981 | controller | API Version:  4.6.2
2025-10-30 00:10:35.087007 | controller | Go Version:   go1.19.12
2025-10-30 00:10:35.087045 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-30 00:10:35.087072 | controller | OS/Arch:      linux/amd64
2025-10-30 00:10:35.460365 | controller | ok: Runtime: 0:00:00.219071
2025-10-30 00:10:35.468800 | 
2025-10-30 00:10:35.468954 | TASK [ensure-podman : Print podman version installed]
2025-10-30 00:10:35.503332 | Podman version: Client:       Podman Engine
2025-10-30 00:10:35.503468 | Version:      4.6.2
2025-10-30 00:10:35.503496 | API Version:  4.6.2
2025-10-30 00:10:35.503516 | Go Version:   go1.19.12
2025-10-30 00:10:35.503534 | Built:        Mon Aug 28 19:38:31 2023
2025-10-30 00:10:35.503552 | OS/Arch:      linux/amd64
2025-10-30 00:10:35.513042 | 
2025-10-30 00:10:35.513134 | TASK [ensure-podman : Validate podman engine]
2025-10-30 00:10:35.683257 | controller | skipping: Conditional result was False
2025-10-30 00:10:35.690154 | 
2025-10-30 00:10:35.690262 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-30 00:10:35.744760 | controller | skipping: Conditional result was False
2025-10-30 00:10:35.756759 | 
2025-10-30 00:10:35.756893 | TASK [Ensure python3.8 is present]
2025-10-30 00:10:35.771743 | controller | skipping: Conditional result was False
2025-10-30 00:10:35.778945 | 
2025-10-30 00:10:35.779091 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-30 00:10:35.805368 | controller | ok
2025-10-30 00:10:35.827329 | 
2025-10-30 00:10:35.827456 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-30 00:10:39.466212 | controller | ok: Nothing to do
2025-10-30 00:10:39.478456 | 
2025-10-30 00:10:39.478626 | TASK [our-ensure-python : Also install python3-devel]
2025-10-30 00:10:52.577672 | controller | changed
2025-10-30 00:10:52.595635 | 
2025-10-30 00:10:52.595803 | TASK [Run ensure-virtualenv role]
2025-10-30 00:10:52.620632 | controller | ok
2025-10-30 00:10:52.652557 | 
2025-10-30 00:10:52.652686 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-30 00:10:53.057523 | controller | /usr/bin/virtualenv
2025-10-30 00:10:53.294694 | controller | ok: Runtime: 0:00:00.004453
2025-10-30 00:10:53.308807 | 
2025-10-30 00:10:53.308982 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-30 00:10:53.338232 | controller | skipping: Conditional result was False
2025-10-30 00:10:53.338569 | controller | ok: All items complete
2025-10-30 00:10:53.338606 | 
2025-10-30 00:10:53.388430 | 
2025-10-30 00:10:53.388560 | TASK [Find the full path of the Python interpreter]
2025-10-30 00:10:53.809297 | controller | /usr/bin/python3
2025-10-30 00:10:54.019001 | controller | ok
2025-10-30 00:10:54.027337 | 
2025-10-30 00:10:54.027527 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-30 00:10:55.477072 | controller | created virtual environment CPython3.11.0.final.0-64 in 769ms
2025-10-30 00:10:55.527904 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-30 00:10:55.528643 | 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-30 00:10:55.528664 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-30 00:10:55.528688 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-30 00:10:55.656598 | controller | changed
2025-10-30 00:10:55.665907 | 
2025-10-30 00:10:55.666258 | TASK [Set selinux package]
2025-10-30 00:10:55.696818 | controller | ok
2025-10-30 00:10:55.702164 | 
2025-10-30 00:10:55.702267 | TASK [Set selinux package (Fedora)]
2025-10-30 00:10:55.731350 | controller | ok
2025-10-30 00:10:55.737306 | 
2025-10-30 00:10:55.737393 | TASK [Install selinux into virtualenv]
2025-10-30 00:10:58.402647 | controller | Collecting selinux-please-lie-to-me
2025-10-30 00:10:58.492242 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-30 00:10:59.018724 | controller | Collecting setuptools<50.0.0
2025-10-30 00:10:59.032779 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-30 00:10:59.160826 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 6.7 MB/s eta 0:00:00
2025-10-30 00:10:59.315791 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-30 00:10:59.316204 | controller |   Attempting uninstall: setuptools
2025-10-30 00:10:59.321237 | controller |     Found existing installation: setuptools 62.6.0
2025-10-30 00:10:59.432991 | controller |     Uninstalling setuptools-62.6.0:
2025-10-30 00:10:59.448220 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-30 00:11:00.216286 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-30 00:11:00.427388 | controller |
2025-10-30 00:11:00.636113 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-30 00:11:00.636163 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-30 00:11:00.901814 | controller | ok: Runtime: 0:00:04.414162
2025-10-30 00:11:00.911157 | 
2025-10-30 00:11:00.911434 | TASK [Install pytest-forked into virtualenv]
2025-10-30 00:11:02.145581 | controller | Collecting pytest-forked
2025-10-30 00:11:02.238202 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-30 00:11:02.310792 | controller | Collecting py
2025-10-30 00:11:02.324336 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-30 00:11:02.360941 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 3.1 MB/s eta 0:00:00
2025-10-30 00:11:02.540461 | controller | Collecting pytest>=3.10
2025-10-30 00:11:02.553976 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-30 00:11:02.618881 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 5.9 MB/s eta 0:00:00
2025-10-30 00:11:02.675961 | controller | Collecting iniconfig>=1
2025-10-30 00:11:02.690084 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-30 00:11:02.757440 | controller | Collecting packaging>=20
2025-10-30 00:11:02.770706 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-30 00:11:02.786168 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 4.4 MB/s eta 0:00:00
2025-10-30 00:11:02.830991 | controller | Collecting pluggy<2,>=1.5
2025-10-30 00:11:02.844348 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-30 00:11:02.921226 | controller | Collecting pygments>=2.7.2
2025-10-30 00:11:02.934517 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-30 00:11:03.064684 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 9.6 MB/s eta 0:00:00
2025-10-30 00:11:03.193958 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-30 00:11:05.397431 | 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-30 00:11:05.413884 | controller |
2025-10-30 00:11:05.592679 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-30 00:11:05.592726 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-30 00:11:06.068362 | controller | ok: Runtime: 0:00:04.198664
2025-10-30 00:11:06.076336 | 
2025-10-30 00:11:06.076437 | TASK [Update pip]
2025-10-30 00:11:07.180363 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-30 00:11:07.417227 | controller | Collecting pip
2025-10-30 00:11:07.512807 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-30 00:11:07.725439 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 8.6 MB/s eta 0:00:00
2025-10-30 00:11:07.869271 | controller | Installing collected packages: pip
2025-10-30 00:11:07.869597 | controller |   Attempting uninstall: pip
2025-10-30 00:11:07.873916 | controller |     Found existing installation: pip 22.2.2
2025-10-30 00:11:08.131389 | controller |     Uninstalling pip-22.2.2:
2025-10-30 00:11:08.161012 | controller |       Successfully uninstalled pip-22.2.2
2025-10-30 00:11:09.863182 | controller | Successfully installed pip-25.3
2025-10-30 00:11:10.225785 | controller | ok: Runtime: 0:00:03.470332
2025-10-30 00:11:10.235151 | 
2025-10-30 00:11:10.235289 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-30 00:11:10.757413 | controller | changed
2025-10-30 00:11:10.782526 | 
2025-10-30 00:11:10.782712 | TASK [Install ansible into virtualenv]
2025-10-30 00:11:11.773375 | controller | Processing ./src/github.com/ansible/ansible
2025-10-30 00:11:11.779680 | controller |   Installing build dependencies: started
2025-10-30 00:11:13.570795 | controller |   Installing build dependencies: finished with status 'done'
2025-10-30 00:11:13.571978 | controller |   Getting requirements to build wheel: started
2025-10-30 00:11:15.096378 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-30 00:11:16.025381 | controller |   Preparing metadata (pyproject.toml): started
2025-10-30 00:11:16.025437 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-30 00:11:16.028658 | 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-30 00:11:16.033610 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-30 00:11:16.459230 | controller | ERROR
2025-10-30 00:11:16.459456 | controller | {
2025-10-30 00:11:16.459497 | controller |   "delta": "0:00:04.965631",
2025-10-30 00:11:16.459526 | controller |   "end": "2025-10-30 00:11:16.180405",
2025-10-30 00:11:16.459552 | controller |   "msg": "non-zero return code",
2025-10-30 00:11:16.459586 | controller |   "rc": 1,
2025-10-30 00:11:16.459611 | controller |   "start": "2025-10-30 00:11:11.214774"
2025-10-30 00:11:16.459634 | controller | }
failure
2025-10-30 00:11:16.461653 | 
2025-10-30 00:11:16.461715 | PLAY RECAP
2025-10-30 00:11:16.461775 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-30 00:11:16.461806 | 
2025-10-30 00:11:16.647998 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-30 00:11:16.649400 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-30 00:11:17.442888 | 
2025-10-30 00:11:17.443034 | PLAY [all]
2025-10-30 00:11:17.472213 | 
2025-10-30 00:11:17.472435 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-30 00:11:18.314477 | controller | changed: non-zero return code
2025-10-30 00:11:18.322479 | 
2025-10-30 00:11:18.322617 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-30 00:11:18.348904 | controller | skipping: Conditional result was False
2025-10-30 00:11:18.356515 | 
2025-10-30 00:11:18.356691 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-30 00:11:18.394463 | 
2025-10-30 00:11:18.394689 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-30 00:11:18.426958 | 
2025-10-30 00:11:18.427152 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-30 00:11:18.453227 | controller | skipping: Conditional result was False
2025-10-30 00:11:18.462704 | 
2025-10-30 00:11:18.462842 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-30 00:11:18.509781 | 
2025-10-30 00:11:18.510051 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-30 00:11:18.537723 | controller | skipping: Conditional result was False
2025-10-30 00:11:18.546829 | 
2025-10-30 00:11:18.547009 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-30 00:11:18.572220 | controller | skipping: Conditional result was False
2025-10-30 00:11:18.580324 | 
2025-10-30 00:11:18.580469 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-30 00:11:18.595283 | controller | skipping: Conditional result was False
2025-10-30 00:11:18.655858 | 
2025-10-30 00:11:18.655984 | PLAY RECAP
2025-10-30 00:11:18.656056 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-30 00:11:18.656093 | 
2025-10-30 00:11:18.822354 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-30 00:11:18.823390 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-30 00:11:19.640597 | 
2025-10-30 00:11:19.640801 | PLAY [all:!appliance*]
2025-10-30 00:11:19.682290 | 
2025-10-30 00:11:19.682450 | TASK [unregister the node]
2025-10-30 00:11:19.848250 | controller | skipping: Conditional result was False
2025-10-30 00:11:19.857231 | 
2025-10-30 00:11:19.857373 | TASK [include_role : fetch-output]
2025-10-30 00:11:19.894212 | controller | ok
2025-10-30 00:11:19.933191 | 
2025-10-30 00:11:19.933337 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-30 00:11:20.000271 | controller | skipping: Conditional result was False
2025-10-30 00:11:20.009771 | 
2025-10-30 00:11:20.009953 | TASK [fetch-output : Set log path for single node]
2025-10-30 00:11:20.069867 | controller | ok
2025-10-30 00:11:20.078834 | 
2025-10-30 00:11:20.079058 | LOOP [fetch-output : Ensure local output dirs]
2025-10-30 00:11:20.586402 | controller -> localhost | ok: "/var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/logs"
2025-10-30 00:11:20.853987 | controller -> localhost | changed: "/var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/artifacts"
2025-10-30 00:11:21.158794 | controller -> localhost | changed: "/var/lib/zuul/builds/fa4f7840e9364593a14dce4e299273a7/work/docs"
2025-10-30 00:11:21.177974 | 
2025-10-30 00:11:21.178138 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-30 00:11:22.481538 | controller | changed:
2025-10-30 00:11:22.481712 | controller | .d..t...... ./
2025-10-30 00:11:22.481739 | controller | cd+++++++++ controller/
2025-10-30 00:11:22.481775 | controller | changed: All items complete
2025-10-30 00:11:22.481795 | 
2025-10-30 00:11:23.624207 | controller | changed: .d..t...... ./
2025-10-30 00:11:24.822206 | controller | changed: .d..t...... ./
2025-10-30 00:11:24.852205 | 
2025-10-30 00:11:24.852393 | TASK [include_role : fetch-output-openshift]
2025-10-30 00:11:24.914392 | controller | skipping: Conditional result was False
2025-10-30 00:11:24.924867 | 
2025-10-30 00:11:24.925080 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-30 00:11:24.990728 | controller | skipping: Conditional result was False
2025-10-30 00:11:24.991625 | controller | skipping: Conditional result was False
2025-10-30 00:11:25.040876 | 
2025-10-30 00:11:25.040991 | PLAY [localhost]
2025-10-30 00:11:25.065076 | 
2025-10-30 00:11:25.065249 | TASK [Run Zuul manifest role]
2025-10-30 00:11:25.097333 | localhost | ok
2025-10-30 00:11:25.138802 | 
2025-10-30 00:11:25.138926 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-30 00:11:25.838520 | localhost | changed
2025-10-30 00:11:25.845610 | 
2025-10-30 00:11:25.845713 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-30 00:11:25.904442 | localhost | ok
2025-10-30 00:11:25.915755 | 
2025-10-30 00:11:25.915863 | TASK [Set zuul-log-path fact]
2025-10-30 00:11:25.936352 | localhost | ok
2025-10-30 00:11:25.973499 | 
2025-10-30 00:11:25.973632 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-30 00:11:26.016764 | localhost | ok
2025-10-30 00:11:26.026195 | 
2025-10-30 00:11:26.026328 | LOOP [Run upload-logs-swift role]
2025-10-30 00:11:26.075436 | localhost | Output suppressed because no_log was given
2025-10-30 00:11:26.140257 | 
2025-10-30 00:11:26.140389 | TASK [Set zuul-log-path fact]
2025-10-30 00:11:26.167413 | localhost | skipping: Conditional result was False
2025-10-30 00:11:26.175372 | 
2025-10-30 00:11:26.175529 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-30 00:11:27.024593 | localhost -> localhost | ok: Runtime: 0:00:00.011343
2025-10-30 00:11:27.089214 | 
2025-10-30 00:11:27.089344 | TASK [upload-logs-swift : Upload logs to swift]