2025-10-27 00:25:42.675408 | Job console starting...
2025-10-27 00:25:42.684342 | Updating repositories
2025-10-27 00:25:42.809016 | Preparing job workspace
2025-10-27 00:25:46.460915 | Running Ansible setup...
2025-10-27 00:25:52.432168 | PRE-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-27 00:25:53.125353 | 
2025-10-27 00:25:53.125526 | PLAY [localhost]
2025-10-27 00:25:53.134659 | 
2025-10-27 00:25:53.134778 | TASK [Gathering Facts]
2025-10-27 00:25:54.293279 | localhost | ok
2025-10-27 00:25:54.329272 | 
2025-10-27 00:25:54.329530 | TASK [Setup log path fact]
2025-10-27 00:25:54.361959 | localhost | ok
2025-10-27 00:25:54.377354 | 
2025-10-27 00:25:54.377509 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-27 00:25:54.418430 | localhost | ok
2025-10-27 00:25:54.427578 | 
2025-10-27 00:25:54.427714 | TASK [emit-job-header : Print job information]
2025-10-27 00:25:54.479212 | # Job Information
2025-10-27 00:25:54.479466 | Ansible Version: 2.15.12
2025-10-27 00:25:54.479513 | Job: ansible-test-sanity-docker-milestone
2025-10-27 00:25:54.479543 | Pipeline: periodic
2025-10-27 00:25:54.479569 | Executor: ze04.softwarefactory-project.io
2025-10-27 00:25:54.479596 | Triggered by: https://github.com/ansible-collections/ansible.network
2025-10-27 00:25:54.479628 | Log URL (when completed): https://ansible.softwarefactory-project.io/logs/54e/ansible/54e4f9bc09d949a0b76f891426a2a34a/
2025-10-27 00:25:54.479655 | Event ID: 750469794ad743fdb26497abfe8a4902
2025-10-27 00:25:54.486112 | 
2025-10-27 00:25:54.486215 | LOOP [emit-job-header : Print node information]
2025-10-27 00:25:54.602556 | localhost | ok:
2025-10-27 00:25:54.603064 | localhost | # Node Information
2025-10-27 00:25:54.603144 | localhost | Inventory Hostname: controller
2025-10-27 00:25:54.603198 | localhost | Hostname: ip-172-16-87-51
2025-10-27 00:25:54.603250 | localhost | Username: zuul-worker
2025-10-27 00:25:54.603312 | localhost | Distro: Fedora 37
2025-10-27 00:25:54.603358 | localhost | Provider: ansible-us-east-2
2025-10-27 00:25:54.603397 | localhost | Region: us-east-2
2025-10-27 00:25:54.603433 | localhost | Label: ansible-fedora-37-1vcpu
2025-10-27 00:25:54.603469 | localhost | Product Name: t3.small
2025-10-27 00:25:54.603506 | localhost | Interface IP: 18.216.99.134
2025-10-27 00:25:54.618793 | 
2025-10-27 00:25:54.618992 | TASK [log-inventory : Ensure Zuul Ansible directory exists]
2025-10-27 00:25:55.096069 | localhost -> localhost | changed
2025-10-27 00:25:55.104915 | 
2025-10-27 00:25:55.105058 | TASK [log-inventory : Copy ansible inventory to logs dir]
2025-10-27 00:25:56.072294 | localhost -> localhost | changed
2025-10-27 00:25:56.099729 | 
2025-10-27 00:25:56.099868 | PLAY [all:!appliance*]
2025-10-27 00:25:56.122264 | 
2025-10-27 00:25:56.122422 | TASK [include_role : start-zuul-console]
2025-10-27 00:25:56.146607 | controller | ok
2025-10-27 00:25:56.163409 | 
2025-10-27 00:25:56.163573 | TASK [start-zuul-console : Start zuul_console daemon.]
2025-10-27 00:25:56.881210 | controller | ok
2025-10-27 00:25:56.900247 | 
2025-10-27 00:25:56.900392 | TASK [use-our-mirror : Retrieve the IP address]
2025-10-27 00:25:59.248464 | controller | ok: Status code was 404 and not [200]: HTTP Error 404: Not Found
2025-10-27 00:25:59.263893 | 
2025-10-27 00:25:59.264042 | TASK [use-our-mirror : Ensure the registry service is running on the mirror]
2025-10-27 00:25:59.427503 | controller | skipping: Conditional result was False
2025-10-27 00:25:59.438894 | 
2025-10-27 00:25:59.439088 | TASK [use-our-mirror : Write the IP in /etc/hosts]
2025-10-27 00:25:59.465161 | controller | skipping: Conditional result was False
2025-10-27 00:25:59.474453 | 
2025-10-27 00:25:59.474580 | TASK [use-our-mirror : Create the podman configuration directory]
2025-10-27 00:25:59.501651 | controller | skipping: Conditional result was False
2025-10-27 00:25:59.511003 | 
2025-10-27 00:25:59.511109 | TASK [use-our-mirror : Copy the podman configuration]
2025-10-27 00:25:59.536036 | controller | skipping: Conditional result was False
2025-10-27 00:25:59.545095 | 
2025-10-27 00:25:59.545201 | TASK [use-our-mirror : Copy the Yum configuration (main)]
2025-10-27 00:25:59.570826 | controller | skipping: Conditional result was False
2025-10-27 00:25:59.580318 | 
2025-10-27 00:25:59.580431 | TASK [use-our-mirror : Copy the Yum configuration (update)]
2025-10-27 00:25:59.605772 | controller | skipping: Conditional result was False
2025-10-27 00:25:59.622027 | 
2025-10-27 00:25:59.622195 | TASK [Disable Fedora Modular]
2025-10-27 00:26:00.367491 | controller | changed
2025-10-27 00:26:00.381966 | 
2025-10-27 00:26:00.382167 | TASK [Enable EPEL]
2025-10-27 00:26:00.422446 | controller | skipping: Conditional result was False
2025-10-27 00:26:00.438815 | 
2025-10-27 00:26:00.438960 | TASK [Register the RHEL node]
2025-10-27 00:26:00.619037 | 
2025-10-27 00:26:00.619345 | TASK [Show the subscription-manager status]
2025-10-27 00:26:00.829417 | controller | skipping: Conditional result was False
2025-10-27 00:26:00.836646 | 
2025-10-27 00:26:00.836749 | TASK [Enable EPEL on RHEL]
2025-10-27 00:26:00.978207 | controller | skipping: Conditional result was False
2025-10-27 00:26:00.991763 | 
2025-10-27 00:26:00.991916 | TASK [Install git and tox]
2025-10-27 00:27:35.582507 | controller | changed
2025-10-27 00:27:35.591417 | 
2025-10-27 00:27:35.591551 | TASK [include_role : prepare-workspace]
2025-10-27 00:27:35.627466 | controller | ok
2025-10-27 00:27:35.660121 | 
2025-10-27 00:27:35.660312 | TASK [prepare-workspace : Start zuul_console daemon.]
2025-10-27 00:27:36.236545 | controller | ok
2025-10-27 00:27:36.249411 | 
2025-10-27 00:27:36.249593 | TASK [prepare-workspace : Synchronize src repos to workspace directory.]
2025-10-27 00:27:49.178724 | controller | Output suppressed because no_log was given
2025-10-27 00:27:49.265195 | 
2025-10-27 00:27:49.265346 | TASK [include_role : prepare-workspace-openshift]
2025-10-27 00:27:49.294243 | controller | skipping: Conditional result was False
2025-10-27 00:27:49.318371 | 
2025-10-27 00:27:49.318467 | PLAY [all:!appliance]
2025-10-27 00:27:49.335639 | 
2025-10-27 00:27:49.335839 | TASK [Run add-build-sshkey role (RSA)]
2025-10-27 00:27:49.367587 | controller | ok
2025-10-27 00:27:49.383736 | 
2025-10-27 00:27:49.383876 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-27 00:27:49.685886 | controller -> localhost | ok
2025-10-27 00:27:49.693462 | 
2025-10-27 00:27:49.693570 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-27 00:27:49.726632 | controller | ok
2025-10-27 00:27:49.744191 | controller | included: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-27 00:27:49.754865 | 
2025-10-27 00:27:49.754988 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-27 00:27:50.335273 | controller -> localhost | Generating public/private rsa key pair.
2025-10-27 00:27:50.335602 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/54e4f9bc09d949a0b76f891426a2a34a_id_rsa.
2025-10-27 00:27:50.335640 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/54e4f9bc09d949a0b76f891426a2a34a_id_rsa.pub.
2025-10-27 00:27:50.335666 | controller -> localhost | The key fingerprint is:
2025-10-27 00:27:50.335842 | controller -> localhost | SHA256:kBCqbq09DXf5g81X/Bi/227b/d6J2Bw17fOnhAVUlrc zuul-build-sshkey
2025-10-27 00:27:50.335877 | controller -> localhost | The key's randomart image is:
2025-10-27 00:27:50.335902 | controller -> localhost | +---[RSA 2048]----+
2025-10-27 00:27:50.335925 | controller -> localhost | |    o.      ..o. |
2025-10-27 00:27:50.335951 | controller -> localhost | |   . . .   . .. .|
2025-10-27 00:27:50.335977 | controller -> localhost | |  .   o     .  ..|
2025-10-27 00:27:50.336000 | controller -> localhost | | .     .     . E.|
2025-10-27 00:27:50.336022 | controller -> localhost | |.       S   . .o.|
2025-10-27 00:27:50.336060 | controller -> localhost | |. .. . o     *...|
2025-10-27 00:27:50.336091 | controller -> localhost | | o .+ . =   o.*..|
2025-10-27 00:27:50.336116 | controller -> localhost | |. o. . . = .+ooo@|
2025-10-27 00:27:50.336140 | controller -> localhost | | . ..     o. +.X/|
2025-10-27 00:27:50.336165 | controller -> localhost | +----[SHA256]-----+
2025-10-27 00:27:50.336230 | controller -> localhost | ok: Runtime: 0:00:00.136153
2025-10-27 00:27:50.346784 | 
2025-10-27 00:27:50.346925 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-27 00:27:50.382737 | controller | ok
2025-10-27 00:27:50.396931 | controller | included: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-27 00:27:50.409822 | 
2025-10-27 00:27:50.410130 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-27 00:27:50.435361 | controller | skipping: Conditional result was False
2025-10-27 00:27:50.444914 | 
2025-10-27 00:27:50.445029 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-27 00:27:51.158033 | controller | changed
2025-10-27 00:27:51.164752 | 
2025-10-27 00:27:51.164825 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-27 00:27:51.536483 | controller | ok
2025-10-27 00:27:51.555262 | 
2025-10-27 00:27:51.555379 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-27 00:27:52.881313 | controller | changed
2025-10-27 00:27:52.889322 | 
2025-10-27 00:27:52.889456 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-27 00:27:54.255436 | controller | changed
2025-10-27 00:27:54.272897 | 
2025-10-27 00:27:54.273383 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-27 00:27:54.315525 | controller | skipping: Conditional result was False
2025-10-27 00:27:54.330389 | 
2025-10-27 00:27:54.330540 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-27 00:27:54.863800 | controller -> localhost | changed
2025-10-27 00:27:54.892378 | 
2025-10-27 00:27:54.892549 | TASK [add-build-sshkey : Add back temp key]
2025-10-27 00:27:55.200228 | controller -> localhost | Identity added: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/54e4f9bc09d949a0b76f891426a2a34a_id_rsa (zuul-build-sshkey)
2025-10-27 00:27:55.200591 | controller -> localhost | ok: Runtime: 0:00:00.012501
2025-10-27 00:27:55.211704 | 
2025-10-27 00:27:55.211884 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-27 00:27:55.817122 | controller | ok
2025-10-27 00:27:55.822748 | 
2025-10-27 00:27:55.822815 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-27 00:27:55.869302 | controller | skipping: Conditional result was False
2025-10-27 00:27:55.881746 | 
2025-10-27 00:27:55.881828 | TASK [Run add-build-sshkey role (ECDSA)]
2025-10-27 00:27:55.914200 | controller | ok
2025-10-27 00:27:55.932509 | 
2025-10-27 00:27:55.932610 | TASK [add-build-sshkey : Check to see if ssh key was already created for this build]
2025-10-27 00:27:56.210963 | controller -> localhost | ok
2025-10-27 00:27:56.222179 | 
2025-10-27 00:27:56.222303 | TASK [add-build-sshkey : Create a new key in workspace based on build UUID]
2025-10-27 00:27:56.254918 | controller | ok
2025-10-27 00:27:56.267631 | controller | included: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/create-key-and-replace.yaml
2025-10-27 00:27:56.275024 | 
2025-10-27 00:27:56.275092 | TASK [add-build-sshkey : Create Temp SSH key]
2025-10-27 00:27:56.564927 | controller -> localhost | Generating public/private ecdsa key pair.
2025-10-27 00:27:56.565187 | controller -> localhost | Your identification has been saved in /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/54e4f9bc09d949a0b76f891426a2a34a_id_ecdsa.
2025-10-27 00:27:56.565228 | controller -> localhost | Your public key has been saved in /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/54e4f9bc09d949a0b76f891426a2a34a_id_ecdsa.pub.
2025-10-27 00:27:56.565269 | controller -> localhost | The key fingerprint is:
2025-10-27 00:27:56.565298 | controller -> localhost | SHA256:2KneVQK9fcy5b8LP1pWARxllzo0wENgv/cMl2Oixy5M zuul-build-sshkey
2025-10-27 00:27:56.565326 | controller -> localhost | The key's randomart image is:
2025-10-27 00:27:56.565353 | controller -> localhost | +---[ECDSA 521]---+
2025-10-27 00:27:56.565378 | controller -> localhost | |         oooo.+o |
2025-10-27 00:27:56.565403 | controller -> localhost | |        ...  =+..|
2025-10-27 00:27:56.565428 | controller -> localhost | |        . .oo+.o.|
2025-10-27 00:27:56.565454 | controller -> localhost | |       o o.+*=o..|
2025-10-27 00:27:56.565479 | controller -> localhost | |      . S oo+=*o.|
2025-10-27 00:27:56.565504 | controller -> localhost | |       .   oo.+o.|
2025-10-27 00:27:56.565529 | controller -> localhost | |      .   .. +..o|
2025-10-27 00:27:56.565552 | controller -> localhost | |     . . .  E oo+|
2025-10-27 00:27:56.565571 | controller -> localhost | |      . .    . =+|
2025-10-27 00:27:56.565588 | controller -> localhost | +----[SHA256]-----+
2025-10-27 00:27:56.565663 | controller -> localhost | ok: Runtime: 0:00:00.019118
2025-10-27 00:27:56.574831 | 
2025-10-27 00:27:56.574927 | TASK [add-build-sshkey : Remote setup ssh keys (linux)]
2025-10-27 00:27:56.608860 | controller | ok
2025-10-27 00:27:56.619089 | controller | included: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/trusted/project_1/opendev.org/zuul/zuul-jobs/roles/add-build-sshkey/tasks/remote-linux.yaml
2025-10-27 00:27:56.630101 | 
2025-10-27 00:27:56.630253 | TASK [add-build-sshkey : Remove previously added zuul-build-sshkey]
2025-10-27 00:27:56.655051 | controller | skipping: Conditional result was False
2025-10-27 00:27:56.662260 | 
2025-10-27 00:27:56.662337 | TASK [add-build-sshkey : Enable access via build key on all nodes]
2025-10-27 00:27:57.136418 | controller | changed
2025-10-27 00:27:57.151337 | 
2025-10-27 00:27:57.151540 | TASK [add-build-sshkey : Make sure user has a .ssh]
2025-10-27 00:27:57.514133 | controller | ok
2025-10-27 00:27:57.522954 | 
2025-10-27 00:27:57.523070 | TASK [add-build-sshkey : Install build private key as SSH key on all nodes]
2025-10-27 00:27:58.832259 | controller | changed
2025-10-27 00:27:58.842122 | 
2025-10-27 00:27:58.842293 | TASK [add-build-sshkey : Install build public key as SSH key on all nodes]
2025-10-27 00:28:00.549838 | controller | changed
2025-10-27 00:28:00.559138 | 
2025-10-27 00:28:00.559331 | TASK [add-build-sshkey : Remote setup ssh keys (windows)]
2025-10-27 00:28:00.588408 | controller | skipping: Conditional result was False
2025-10-27 00:28:00.604574 | 
2025-10-27 00:28:00.605066 | TASK [remove-zuul-sshkey : Remove master key from local agent]
2025-10-27 00:28:00.880985 | controller -> localhost | changed
2025-10-27 00:28:00.960731 | 
2025-10-27 00:28:00.960885 | TASK [add-build-sshkey : Add back temp key]
2025-10-27 00:28:01.251819 | controller -> localhost | Identity added: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/54e4f9bc09d949a0b76f891426a2a34a_id_ecdsa (zuul-build-sshkey)
2025-10-27 00:28:01.252356 | controller -> localhost | ok: Runtime: 0:00:00.014963
2025-10-27 00:28:01.269643 | 
2025-10-27 00:28:01.269951 | TASK [add-build-sshkey : Verify we can still SSH to all nodes]
2025-10-27 00:28:02.242860 | controller | ok
2025-10-27 00:28:02.252304 | 
2025-10-27 00:28:02.252407 | TASK [add-build-sshkey : Verify we can still SSH to all nodes (windows)]
2025-10-27 00:28:02.277836 | controller | skipping: Conditional result was False
2025-10-27 00:28:02.294368 | 
2025-10-27 00:28:02.294495 | TASK [include_role : remove-zuul-sshkey]
2025-10-27 00:28:02.320041 | controller | skipping: Conditional result was False
2025-10-27 00:28:02.329943 | 
2025-10-27 00:28:02.330055 | LOOP [ensure-output-dirs : Empty Zuul Output directories by removing them]
2025-10-27 00:28:03.145854 | controller | ok: "logs"
2025-10-27 00:28:03.146361 | controller | ok: All items complete
2025-10-27 00:28:03.146427 | 
2025-10-27 00:28:04.041935 | controller | ok: "artifacts"
2025-10-27 00:28:04.522879 | controller | ok: "docs"
2025-10-27 00:28:04.539978 | 
2025-10-27 00:28:04.540104 | LOOP [ensure-output-dirs : Ensure Zuul Output directories exist]
2025-10-27 00:28:04.901136 | controller | changed: "logs"
2025-10-27 00:28:05.210564 | controller | changed: "artifacts"
2025-10-27 00:28:05.506168 | controller | changed: "docs"
2025-10-27 00:28:05.582916 | 
2025-10-27 00:28:05.583099 | PLAY RECAP
2025-10-27 00:28:05.583158 | controller | ok: 30 changed: 16 unreachable: 0 failed: 0 skipped: 18 rescued: 0 ignored: 0
2025-10-27 00:28:05.583221 | localhost | ok: 6 changed: 2 unreachable: 0 failed: 0 skipped: 0 rescued: 0 ignored: 0
2025-10-27 00:28:05.583243 | 
2025-10-27 00:28:05.781381 | PRE-RUN END RESULT_NORMAL: [trusted : github.com/ansible/zuul-config/playbooks/base/pre.yaml@master]
2025-10-27 00:28:05.782337 | PRE-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-27 00:28:06.370383 | 
2025-10-27 00:28:06.370526 | PLAY [all]
2025-10-27 00:28:06.395115 | 
2025-10-27 00:28:06.395317 | TASK [Install binary dependencies]
2025-10-27 00:28:06.466276 | controller | ok
2025-10-27 00:28:06.493232 | 
2025-10-27 00:28:06.493401 | TASK [bindep : Include find tasks]
2025-10-27 00:28:06.524349 | controller | ok
2025-10-27 00:28:06.532531 | controller | included: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/bindep/tasks/find.yaml
2025-10-27 00:28:06.539072 | 
2025-10-27 00:28:06.539178 | TASK [bindep : Look for bindep.txt]
2025-10-27 00:28:07.148404 | controller | ok
2025-10-27 00:28:07.161573 | 
2025-10-27 00:28:07.161724 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:28:07.186736 | controller | skipping: Conditional result was False
2025-10-27 00:28:07.193946 | 
2025-10-27 00:28:07.194040 | TASK [bindep : Look for other-requirements.txt]
2025-10-27 00:28:07.524571 | controller | ok
2025-10-27 00:28:07.532177 | 
2025-10-27 00:28:07.532250 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:28:07.557611 | controller | skipping: Conditional result was False
2025-10-27 00:28:07.565500 | 
2025-10-27 00:28:07.565606 | TASK [bindep : Look for bindep fallback file]
2025-10-27 00:28:07.609017 | controller | skipping: Conditional result was False
2025-10-27 00:28:07.616034 | 
2025-10-27 00:28:07.616130 | TASK [bindep : Define bindep_file fact]
2025-10-27 00:28:07.641078 | controller | skipping: Conditional result was False
2025-10-27 00:28:07.647986 | 
2025-10-27 00:28:07.648092 | TASK [bindep : Include bindep tasks]
2025-10-27 00:28:07.673130 | controller | skipping: Conditional result was False
2025-10-27 00:28:07.682974 | 
2025-10-27 00:28:07.683097 | TASK [bindep : Include install tasks]
2025-10-27 00:28:07.722244 | controller | skipping: Conditional result was False
2025-10-27 00:28:07.730336 | 
2025-10-27 00:28:07.730454 | LOOP [bindep : Include package tasks]
2025-10-27 00:28:07.789392 | 
2025-10-27 00:28:07.789593 | TASK [Run test-setup role]
2025-10-27 00:28:07.809144 | controller | ok
2025-10-27 00:28:07.828538 | 
2025-10-27 00:28:07.828643 | TASK [test-setup : Check if project's tools/test-setup.sh exists]
2025-10-27 00:28:08.125640 | controller | ok
2025-10-27 00:28:08.131861 | 
2025-10-27 00:28:08.131932 | TASK [test-setup : Run tools/test-setup.sh]
2025-10-27 00:28:08.267848 | controller | skipping: Conditional result was False
2025-10-27 00:28:08.306868 | 
2025-10-27 00:28:08.306999 | PLAY RECAP
2025-10-27 00:28:08.307046 | controller | ok: 4 changed: 0 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-27 00:28:08.307066 | 
2025-10-27 00:28:08.450743 | PRE-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/pre.yaml@master]
2025-10-27 00:28:08.451760 | PRE-RUN START: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-27 00:28:09.069348 | 
2025-10-27 00:28:09.069513 | PLAY [controller]
2025-10-27 00:28:09.091052 | 
2025-10-27 00:28:09.091194 | TASK [Create the /root directory]
2025-10-27 00:28:09.838197 | controller | ok
2025-10-27 00:28:09.850372 | 
2025-10-27 00:28:09.850510 | TASK [Install glibc-langpack-en]
2025-10-27 00:28:18.019427 | controller | ok: Nothing to do
2025-10-27 00:28:18.025054 | 
2025-10-27 00:28:18.025124 | TASK [Ensure controller directory exists]
2025-10-27 00:28:18.459524 | controller | changed
2025-10-27 00:28:18.471297 | 
2025-10-27 00:28:18.471439 | TASK [Install container runtime]
2025-10-27 00:28:18.529798 | controller | ok
2025-10-27 00:28:18.592461 | 
2025-10-27 00:28:18.592624 | LOOP [ensure-podman : Find distribution installation]
2025-10-27 00:28:18.642104 | controller | ok: "/var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml"
2025-10-27 00:28:18.660448 | controller | included: /var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/untrusted/project_0/opendev.org/zuul/zuul-jobs/roles/ensure-podman/tasks/RedHat.yaml
2025-10-27 00:28:18.669562 | 
2025-10-27 00:28:18.669767 | TASK [ensure-podman : Install podman (RedHat)]
2025-10-27 00:29:37.592909 | controller | changed
2025-10-27 00:29:37.599975 | 
2025-10-27 00:29:37.600066 | TASK [ensure-podman : Fetch podman version]
2025-10-27 00:29:38.328984 | controller | Client:       Podman Engine
2025-10-27 00:29:38.329065 | controller | Version:      4.6.2
2025-10-27 00:29:38.329095 | controller | API Version:  4.6.2
2025-10-27 00:29:38.329122 | controller | Go Version:   go1.19.12
2025-10-27 00:29:38.329160 | controller | Built:        Mon Aug 28 19:38:31 2023
2025-10-27 00:29:38.329187 | controller | OS/Arch:      linux/amd64
2025-10-27 00:29:38.753336 | controller | ok: Runtime: 0:00:00.219592
2025-10-27 00:29:38.761457 | 
2025-10-27 00:29:38.761562 | TASK [ensure-podman : Print podman version installed]
2025-10-27 00:29:38.793387 | Podman version: Client:       Podman Engine
2025-10-27 00:29:38.793561 | Version:      4.6.2
2025-10-27 00:29:38.793589 | API Version:  4.6.2
2025-10-27 00:29:38.793609 | Go Version:   go1.19.12
2025-10-27 00:29:38.793627 | Built:        Mon Aug 28 19:38:31 2023
2025-10-27 00:29:38.793645 | OS/Arch:      linux/amd64
2025-10-27 00:29:38.799073 | 
2025-10-27 00:29:38.799137 | TASK [ensure-podman : Validate podman engine]
2025-10-27 00:29:38.936872 | controller | skipping: Conditional result was False
2025-10-27 00:29:38.943837 | 
2025-10-27 00:29:38.943923 | TASK [ensure-podman : Set up docker compatability socket]
2025-10-27 00:29:38.958873 | controller | skipping: Conditional result was False
2025-10-27 00:29:38.985209 | 
2025-10-27 00:29:38.985422 | TASK [Ensure python3.8 is present]
2025-10-27 00:29:39.011431 | controller | skipping: Conditional result was False
2025-10-27 00:29:39.021826 | 
2025-10-27 00:29:39.022002 | TASK [Run our-ensure-python role (Fedora only for now)]
2025-10-27 00:29:39.048496 | controller | ok
2025-10-27 00:29:39.075382 | 
2025-10-27 00:29:39.075526 | TASK [our-ensure-python : Install the right Python version (rpm)]
2025-10-27 00:29:42.895477 | controller | ok: Nothing to do
2025-10-27 00:29:42.908603 | 
2025-10-27 00:29:42.908971 | TASK [our-ensure-python : Also install python3-devel]
2025-10-27 00:29:56.807746 | controller | changed
2025-10-27 00:29:56.835312 | 
2025-10-27 00:29:56.836213 | TASK [Run ensure-virtualenv role]
2025-10-27 00:29:56.862843 | controller | ok
2025-10-27 00:29:56.896709 | 
2025-10-27 00:29:56.896900 | TASK [ensure-virtualenv : Check if virtualenv is installed]
2025-10-27 00:29:57.320532 | controller | /usr/bin/virtualenv
2025-10-27 00:29:57.537072 | controller | ok: Runtime: 0:00:00.005090
2025-10-27 00:29:57.547949 | 
2025-10-27 00:29:57.548156 | LOOP [ensure-virtualenv : Install virtualenv package]
2025-10-27 00:29:57.570865 | controller | skipping: Conditional result was False
2025-10-27 00:29:57.571207 | controller | ok: All items complete
2025-10-27 00:29:57.571237 | 
2025-10-27 00:29:57.591903 | 
2025-10-27 00:29:57.592103 | TASK [Find the full path of the Python interpreter]
2025-10-27 00:29:58.055978 | controller | /usr/bin/python3
2025-10-27 00:29:58.240917 | controller | ok
2025-10-27 00:29:58.249566 | 
2025-10-27 00:29:58.249664 | TASK [Create virtualenv for ansible-test with a specific interpreter]
2025-10-27 00:29:59.714323 | controller | created virtual environment CPython3.11.0.final.0-64 in 769ms
2025-10-27 00:29:59.770318 | controller |   creator CPython3Posix(dest=/home/zuul-worker/venv, clear=False, no_vcs_ignore=False, global=False)
2025-10-27 00:29:59.771000 | 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-27 00:29:59.771024 | controller |     added seed packages: pip==22.2.2, setuptools==62.6.0, wheel==0.37.1
2025-10-27 00:29:59.771046 | controller |   activators BashActivator,CShellActivator,FishActivator,NushellActivator,PowerShellActivator,PythonActivator
2025-10-27 00:29:59.892287 | controller | changed
2025-10-27 00:29:59.901589 | 
2025-10-27 00:29:59.901724 | TASK [Set selinux package]
2025-10-27 00:29:59.940866 | controller | ok
2025-10-27 00:29:59.951190 | 
2025-10-27 00:29:59.951364 | TASK [Set selinux package (Fedora)]
2025-10-27 00:29:59.995283 | controller | ok
2025-10-27 00:30:00.000920 | 
2025-10-27 00:30:00.001001 | TASK [Install selinux into virtualenv]
2025-10-27 00:30:03.369284 | controller | Collecting selinux-please-lie-to-me
2025-10-27 00:30:03.643705 | controller |   Downloading selinux_please_lie_to_me-1.0.1-py2.py3-none-any.whl (3.8 kB)
2025-10-27 00:30:04.360936 | controller | Collecting setuptools<50.0.0
2025-10-27 00:30:04.472518 | controller |   Downloading setuptools-49.6.0-py3-none-any.whl (803 kB)
2025-10-27 00:30:04.635076 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 803.3/803.3 kB 5.6 MB/s eta 0:00:00
2025-10-27 00:30:04.845184 | controller | Installing collected packages: setuptools, selinux-please-lie-to-me
2025-10-27 00:30:04.845517 | controller |   Attempting uninstall: setuptools
2025-10-27 00:30:04.850679 | controller |     Found existing installation: setuptools 62.6.0
2025-10-27 00:30:04.991197 | controller |     Uninstalling setuptools-62.6.0:
2025-10-27 00:30:05.009659 | controller |       Successfully uninstalled setuptools-62.6.0
2025-10-27 00:30:05.835427 | controller | Successfully installed selinux-please-lie-to-me-1.0.1 setuptools-49.6.0
2025-10-27 00:30:06.052411 | controller |
2025-10-27 00:30:06.274797 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-27 00:30:06.274849 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-27 00:30:06.702850 | controller | ok: Runtime: 0:00:05.778062
2025-10-27 00:30:06.716330 | 
2025-10-27 00:30:06.716535 | TASK [Install pytest-forked into virtualenv]
2025-10-27 00:30:07.968918 | controller | Collecting pytest-forked
2025-10-27 00:30:08.062695 | controller |   Downloading pytest_forked-1.6.0-py3-none-any.whl (4.9 kB)
2025-10-27 00:30:08.123512 | controller | Collecting py
2025-10-27 00:30:08.138304 | controller |   Downloading py-1.11.0-py2.py3-none-any.whl (98 kB)
2025-10-27 00:30:08.175262 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 98.7/98.7 kB 2.9 MB/s eta 0:00:00
2025-10-27 00:30:08.353800 | controller | Collecting pytest>=3.10
2025-10-27 00:30:08.368250 | controller |   Downloading pytest-8.4.2-py3-none-any.whl (365 kB)
2025-10-27 00:30:08.420038 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 365.8/365.8 kB 7.5 MB/s eta 0:00:00
2025-10-27 00:30:08.492633 | controller | Collecting iniconfig>=1
2025-10-27 00:30:08.508591 | controller |   Downloading iniconfig-2.3.0-py3-none-any.whl (7.5 kB)
2025-10-27 00:30:08.588176 | controller | Collecting packaging>=20
2025-10-27 00:30:08.601877 | controller |   Downloading packaging-25.0-py3-none-any.whl (66 kB)
2025-10-27 00:30:08.611005 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 66.5/66.5 kB 8.8 MB/s eta 0:00:00
2025-10-27 00:30:08.656004 | controller | Collecting pluggy<2,>=1.5
2025-10-27 00:30:08.670048 | controller |   Downloading pluggy-1.6.0-py3-none-any.whl (20 kB)
2025-10-27 00:30:08.743948 | controller | Collecting pygments>=2.7.2
2025-10-27 00:30:08.757776 | controller |   Downloading pygments-2.19.2-py3-none-any.whl (1.2 MB)
2025-10-27 00:30:08.852250 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.2/1.2 MB 13.4 MB/s eta 0:00:00
2025-10-27 00:30:08.984998 | controller | Installing collected packages: pygments, py, pluggy, packaging, iniconfig, pytest, pytest-forked
2025-10-27 00:30:11.272056 | 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-27 00:30:11.288199 | controller |
2025-10-27 00:30:11.474573 | controller | [notice] A new release of pip available: 22.2.2 -> 25.3
2025-10-27 00:30:11.474619 | controller | [notice] To update, run: python -m pip install --upgrade pip
2025-10-27 00:30:11.902004 | controller | ok: Runtime: 0:00:04.253318
2025-10-27 00:30:11.908350 | 
2025-10-27 00:30:11.908423 | TASK [Update pip]
2025-10-27 00:30:13.136984 | controller | Requirement already satisfied: pip in ./venv/lib/python3.11/site-packages (22.2.2)
2025-10-27 00:30:13.386950 | controller | Collecting pip
2025-10-27 00:30:13.490699 | controller |   Downloading pip-25.3-py3-none-any.whl (1.8 MB)
2025-10-27 00:30:13.670999 | controller |      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 1.8/1.8 MB 10.1 MB/s eta 0:00:00
2025-10-27 00:30:13.841237 | controller | Installing collected packages: pip
2025-10-27 00:30:13.843001 | controller |   Attempting uninstall: pip
2025-10-27 00:30:13.848603 | controller |     Found existing installation: pip 22.2.2
2025-10-27 00:30:14.108163 | controller |     Uninstalling pip-22.2.2:
2025-10-27 00:30:14.138323 | controller |       Successfully uninstalled pip-22.2.2
2025-10-27 00:30:15.910637 | controller | Successfully installed pip-25.3
2025-10-27 00:30:16.606814 | controller | ok: Runtime: 0:00:03.622741
2025-10-27 00:30:16.620314 | 
2025-10-27 00:30:16.620456 | TASK [Ensure pip temp directory exists in /var/tmp]
2025-10-27 00:30:17.165670 | controller | changed
2025-10-27 00:30:17.173038 | 
2025-10-27 00:30:17.173134 | TASK [Install ansible into virtualenv]
2025-10-27 00:30:18.204731 | controller | Processing ./src/github.com/ansible/ansible
2025-10-27 00:30:18.211462 | controller |   Installing build dependencies: started
2025-10-27 00:30:20.290435 | controller |   Installing build dependencies: finished with status 'done'
2025-10-27 00:30:20.291436 | controller |   Getting requirements to build wheel: started
2025-10-27 00:30:21.842673 | controller |   Getting requirements to build wheel: finished with status 'done'
2025-10-27 00:30:21.844132 | controller |   Preparing metadata (pyproject.toml): started
2025-10-27 00:30:22.774433 | controller |   Preparing metadata (pyproject.toml): finished with status 'done'
2025-10-27 00:30:22.776448 | 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-27 00:30:22.781234 | controller | ERROR: Package 'ansible-core' requires a different Python: 3.11.0 not in '>=3.12'
2025-10-27 00:30:23.356232 | controller | ERROR
2025-10-27 00:30:23.356524 | controller | {
2025-10-27 00:30:23.356586 | controller |   "delta": "0:00:05.299930",
2025-10-27 00:30:23.356627 | controller |   "end": "2025-10-27 00:30:22.928065",
2025-10-27 00:30:23.356664 | controller |   "msg": "non-zero return code",
2025-10-27 00:30:23.356766 | controller |   "rc": 1,
2025-10-27 00:30:23.356807 | controller |   "start": "2025-10-27 00:30:17.628135"
2025-10-27 00:30:23.356842 | controller | }
failure
2025-10-27 00:30:23.359633 | 
2025-10-27 00:30:23.359803 | PLAY RECAP
2025-10-27 00:30:23.359891 | controller | ok: 18 changed: 10 unreachable: 0 failed: 1 skipped: 4 rescued: 0 ignored: 0
2025-10-27 00:30:23.359935 | 
2025-10-27 00:30:23.505796 | PRE-RUN END RESULT_NORMAL: [untrusted : github.com/ansible/ansible-zuul-jobs/playbooks/ansible-test-base/pre.yaml@master]
2025-10-27 00:30:23.506891 | POST-RUN START: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-27 00:30:24.196020 | 
2025-10-27 00:30:24.196165 | PLAY [all]
2025-10-27 00:30:24.219008 | 
2025-10-27 00:30:24.219161 | TASK [fetch-subunit-output : Find stestr or testr executable]
2025-10-27 00:30:25.036317 | controller | changed: non-zero return code
2025-10-27 00:30:25.050772 | 
2025-10-27 00:30:25.050966 | TASK [fetch-subunit-output : Get the list of directories with subunit files]
2025-10-27 00:30:25.079498 | controller | skipping: Conditional result was False
2025-10-27 00:30:25.094826 | 
2025-10-27 00:30:25.095037 | LOOP [fetch-subunit-output : Find any inflight partial subunit files]
2025-10-27 00:30:25.138779 | 
2025-10-27 00:30:25.139085 | LOOP [fetch-subunit-output : Copy any inflight subunit files]
2025-10-27 00:30:25.183126 | 
2025-10-27 00:30:25.183428 | TASK [fetch-subunit-output : Create a temporary file to store the subunit stream]
2025-10-27 00:30:25.211331 | controller | skipping: Conditional result was False
2025-10-27 00:30:25.227215 | 
2025-10-27 00:30:25.227459 | LOOP [fetch-subunit-output : Generate subunit file]
2025-10-27 00:30:25.266994 | 
2025-10-27 00:30:25.267214 | TASK [fetch-subunit-output : Copy the combined subunit file to the zuul work directory]
2025-10-27 00:30:25.292538 | controller | skipping: Conditional result was False
2025-10-27 00:30:25.301236 | 
2025-10-27 00:30:25.301346 | TASK [fetch-subunit-output : Remove the temporary file]
2025-10-27 00:30:25.317087 | controller | skipping: Conditional result was False
2025-10-27 00:30:25.337418 | 
2025-10-27 00:30:25.337594 | TASK [fetch-subunit-output : Process and fetch subunit results]
2025-10-27 00:30:25.356047 | controller | skipping: Conditional result was False
2025-10-27 00:30:25.393339 | 
2025-10-27 00:30:25.393451 | PLAY RECAP
2025-10-27 00:30:25.393509 | controller | ok: 1 changed: 1 unreachable: 0 failed: 0 skipped: 8 rescued: 0 ignored: 0
2025-10-27 00:30:25.393538 | 
2025-10-27 00:30:25.506673 | POST-RUN END RESULT_NORMAL: [untrusted : opendev.org/zuul/zuul-jobs/playbooks/unittests/post.yaml@master]
2025-10-27 00:30:25.507864 | POST-RUN START: [trusted : github.com/ansible/zuul-config/playbooks/base/post.yaml@master]
2025-10-27 00:30:26.147937 | 
2025-10-27 00:30:26.148074 | PLAY [all:!appliance*]
2025-10-27 00:30:26.169971 | 
2025-10-27 00:30:26.170129 | TASK [unregister the node]
2025-10-27 00:30:26.312165 | controller | skipping: Conditional result was False
2025-10-27 00:30:26.325624 | 
2025-10-27 00:30:26.325969 | TASK [include_role : fetch-output]
2025-10-27 00:30:26.360026 | controller | ok
2025-10-27 00:30:26.401002 | 
2025-10-27 00:30:26.401213 | TASK [fetch-output : Set log path for multiple nodes]
2025-10-27 00:30:26.467648 | controller | skipping: Conditional result was False
2025-10-27 00:30:26.476345 | 
2025-10-27 00:30:26.476537 | TASK [fetch-output : Set log path for single node]
2025-10-27 00:30:26.522497 | controller | ok
2025-10-27 00:30:26.535056 | 
2025-10-27 00:30:26.535186 | LOOP [fetch-output : Ensure local output dirs]
2025-10-27 00:30:26.948061 | controller -> localhost | ok: "/var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/logs"
2025-10-27 00:30:27.174872 | controller -> localhost | changed: "/var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/artifacts"
2025-10-27 00:30:27.420899 | controller -> localhost | changed: "/var/lib/zuul/builds/54e4f9bc09d949a0b76f891426a2a34a/work/docs"
2025-10-27 00:30:27.440698 | 
2025-10-27 00:30:27.440843 | LOOP [fetch-output : Collect logs, artifacts and docs]
2025-10-27 00:30:28.753053 | controller | changed:
2025-10-27 00:30:28.753793 | controller | .d..t...... ./
2025-10-27 00:30:28.753903 | controller | cd+++++++++ controller/
2025-10-27 00:30:28.753990 | controller | changed: All items complete
2025-10-27 00:30:28.754040 | 
2025-10-27 00:30:29.934813 | controller | changed: .d..t...... ./
2025-10-27 00:30:31.037990 | controller | changed: .d..t...... ./
2025-10-27 00:30:31.064792 | 
2025-10-27 00:30:31.064948 | TASK [include_role : fetch-output-openshift]
2025-10-27 00:30:31.092191 | controller | skipping: Conditional result was False
2025-10-27 00:30:31.101252 | 
2025-10-27 00:30:31.101366 | LOOP [merge-output-to-logs : Move artifacts and docs to logs dir]
2025-10-27 00:30:31.146468 | controller | skipping: Conditional result was False
2025-10-27 00:30:31.162874 | controller | skipping: Conditional result was False
2025-10-27 00:30:31.199611 | 
2025-10-27 00:30:31.199742 | PLAY [localhost]
2025-10-27 00:30:31.212357 | 
2025-10-27 00:30:31.212455 | TASK [Run Zuul manifest role]
2025-10-27 00:30:31.232440 | localhost | ok
2025-10-27 00:30:31.246063 | 
2025-10-27 00:30:31.246137 | TASK [generate-zuul-manifest : Generate Zuul manifest]
2025-10-27 00:30:31.698316 | localhost | changed
2025-10-27 00:30:31.709990 | 
2025-10-27 00:30:31.710133 | TASK [generate-zuul-manifest : Return Zuul manifest URL to Zuul]
2025-10-27 00:30:31.744325 | localhost | ok
2025-10-27 00:30:31.756339 | 
2025-10-27 00:30:31.756478 | TASK [Set zuul-log-path fact]
2025-10-27 00:30:31.779733 | localhost | ok
2025-10-27 00:30:31.799952 | 
2025-10-27 00:30:31.800069 | TASK [set-zuul-log-path-fact : Set log path for a build]
2025-10-27 00:30:31.841187 | localhost | ok
2025-10-27 00:30:31.851777 | 
2025-10-27 00:30:31.851933 | LOOP [Run upload-logs-swift role]
2025-10-27 00:30:31.908356 | localhost | Output suppressed because no_log was given
2025-10-27 00:30:31.942698 | 
2025-10-27 00:30:31.942829 | TASK [Set zuul-log-path fact]
2025-10-27 00:30:31.978474 | localhost | skipping: Conditional result was False
2025-10-27 00:30:31.984819 | 
2025-10-27 00:30:31.984900 | TASK [upload-logs-swift : Ensure logs are readable before uploading]
2025-10-27 00:30:32.458721 | localhost -> localhost | ok: Runtime: 0:00:00.006037
2025-10-27 00:30:32.464657 | 
2025-10-27 00:30:32.464755 | TASK [upload-logs-swift : Upload logs to swift]